Adventures while building a Silverlight Enterprise application part #37

In this post we are looking at Entity Framework and specifically at some performance quirks.

The story

Recently we were testing part of our new software. One thing we noticed is that, besides the fact that the first time we load data, things are slow because of services starting up and Entity Framework loading metadata, also the first time we save some data, it is also slow.

We decided that is was worth investigating why this was happening. The goal was to at least come up with an explanation and some more insight into when this was occurring.

Analysis

Some preliminary analysis I made:

• This was not the same thing as starting up the service and Entity Framework loading metadata because of that. I knew that because I had just loaded data from the same service and model that I was now saving to.
• It was caused by something in the service. I could tell because we have a busy indicator active whenever a service request is pending completion.
• It was not caused by any specific code for one of our business objects as it didn’t matter which object I would save. It was always slow the first time.

As you may know, if you are following this series for some time, we have a bunch of complex generic code that’s involved when either loading or saving data. I decided my first task was to identify exactly what line or section of code was causing the delay the first time around. To accomplish this I placed some debug code which would log the exact time to the debug output. This way I could easily calculate where a delay would occur.

By following this strategy I quickly found out that the delay for the first save occurred when calling SaveChanges on our model. However, reflecting the code for the method did not reveal any obvious cause for this. I searched on the internet to find out if anyone had already cracked this problem, to find out that only a handful of people had seen the same issue, but non of them actually resolved it.

As I still did not pinpoint the exact cause, I decided to build a test application to demonstrate the problem and hopefully get a better understanding. As we are currently still using version 2.0 of Entity Framework and running in .NET framework 3.5, I used Visual Studio 2008 to build my test application on top of the AdventureWorks database. I needed it to do basically two things:

1. Load a single object from the model to initialize the Entity Framework model
2. Save a change to a single object from the model and time the operation

To make my tests more flexible I decided on a WPF UI that allows me to control the above steps and it presents me with the results instantly. Check out the screenshot below:

The times displayed are in milliseconds. Let me explain what you see here. On top are two rows of buttons, one for the full AdventureWorks model and one for a model with only the Customers table (both models do connect to the same database). Below that is a listbox with performance results for each save action. At the bottom there is a general log to see what is happening.

Basically what you see in the performance logs is this. The first save action is done after loading a customer from the complete model. It takes a whopping 177ms. The next save action, after loading the same record again, takes only 2ms! This reproduces the issue we’ve been having.

Now the next step is doing exactly the same thing with a model that contains only the Customers table, so there is a lot less metadata to be loaded. It should be noted that both models are placed in separate assemblies to make sure metadata of one model is not interfering with the other. The time differences are a lot smaller between the first save (28ms) and the second save (4ms). Note that as performance is reaching lower limits times can fluctuate because of other processes on the system, which can account for the 2ms increase between the large model and the small model.

Because of this we can now conclude that Entity Framework loads some metadata as the first save occurs. Unfortunately we can not do much about that, but at least we now have an explanation.

Taking the next step

But the research didn’t end there. One of my colleagues suggested testing this with .NET 4.0 and Entity Framework 4.0 to see if there would be an improvement there. So I converted the project to Visual Studio 2010 and recreated both models using Entity Framework 4.0. The times are like this:

• Saving the first time on the complete model: 82ms
• Saving the second time on the complete model: 7ms
• Saving the first time on the single table model: 36ms
• Saving the second time on the single table model: 3ms

So work has been done in Entity Framework 4.0 to improve performance while loading metadata. Please note that my measurements were made on a system that is not exactly high performance and thus the measurements are not very accurate, however the differences between EF 2.0 and EF 4.0 with the first save are still significant enough.

Downloads

You can download the source of both versions of my test application:

• Entity framework 2.0 test application
• Entity framework 4.0 test application

Please be aware that the first project is a Visual Studio 2008 project and the second one is a Visual Studio 2010 project. You can however upgrade the first project, without changing the results.

Conclusion

So, although we can’t improve the performance of the first save action on an entity framework model right away, at least we can now explain what happens and what is the actual impact. As this only happens when IIS recycles the Application Pool for our web service, the impact is minimal. Also we can soften the pain as soon as we migrate our service to Entity framework 4.0.

I hope you have learned as much as I have writing this post. If you have any questions, please leave a comment below and I’ll be happy to help you out.