In this post we’ll look into analyzing performance in a Silverlight Line Of Business application, including multiple service layers and we come across a common problem using ADO.NET Entity Framework including a not so obvious solution.
The story
At the moment we are working on getting out a deliverable to a group of customers as soon as possible. However, one of the issues that keeps coming up is performance. A general response by a lot of developers is to just scour the web for performance tips on different technologies used in the stack and apply as many of them as they possibly can. However I find it much more useful to analyze the problem first.
Getting some data
To get a better feel for the problem, I first needed to get some numbers. When starting out with a performance issue the first question to get answered is “where is most time being spend?” This usually leads to the point where most time is being wasted as well.
At first I started out with profiling our application with Visual Studio 2010, but this wasn’t very useful to us as it didn’t show us any data on communicating with the service. I do feel compelled to link to some useful information on profiling your Silverlight application as it isn’t available through the IDE just yet and it requires you to jump through some hoops to get it to actually show you any performance data on your code. You can find a decent post by Oren Nachman on this here.
I should mention that profiling our application revealed one small performance issue with creating dynamic objects, which we use to instantiate modules in our application based on authorization and application settings. However, looking at the big picture it is hardly relevant to us, while hard to remedy it in a good way for our application.
The next step for me was to actually get data on communication with our services. As we designed our application in a way that we abstracted our service connections in seperate generic classes and we use generic service calls to get to our data, the easiest way for me was to simply record the DateTime.Now.Ticks. To keep the impact of this as low as possible on any production scenarios, I decided to write this information to the VS debug window, through Debug.WriteLine. Also to make sure this can be turned off easily to allow for other verbose debugging information, I introduced a conditional compilation symbol called DEBUGGINGPERFORMANCE and wrapped all my recording code with it. The code for me looked something like this:
1: #if DEBUGGINGPERFORMANCE
2: Debug.WriteLine("BusinessLayerConnection.GetDataAsync<{0}>({1}): {2}", typeof(T).Name, id, DateTime.Now.Ticks);
3: #endif
Running the application with this debugging code gave me some interesting data pointing me towards a specific operation, which gets all the data for a particular module at once. Within that set of modules one stood out that was taking far longer then the other modules, so I decided to investigate that further. I decided to use Fiddler to make sure none of this is actually caused by bandwidth issues. The statistics clearly showed my that the problem was with the service taking up a lot of time before actually starting to send a response.
This led me to put similar code in the webservice. Note that Debug.WriteLine doesn’t support the format approach by default and you should wrap that in string.Format. To actually make for a better performance test, I decided to build a small test tool to just make the same service calls several times in a row. This makes sure we’re working with correct numbers instead of chasing some random external factor.
As I started testing like this, I found out there where a lot of messages in the debug output stating that ‘A first change exception of type ‘ had occurred. In this case a large part of these exceptions where related to another service we use, which couldn’t access one of our databases. This was obviously an easy fix and it did improve performance considerably.
Fixing a common Entity Framework problem
After getting one exception out of the way, I found there where some more exceptions being thrown. The exact message that was displayed was: A first chance exception of type 'System.NotSupportedException' occurred in mscorlib.dll. Performance data indicated that this took roughly 3 seconds for six exceptions in each request!
I found it weird to see an exception like this. A web search didn’t return anything useful, except that it could be related to Entity Framework somehow. A forum thread pointed to this bug report about dynamic assemblies, which in itself wasn’t very useful information either.
I also found people asking questions about this message all over the internet, but without any real solutions. I turned on the System.NotSupportedException in Visual Studio, attached it to the service for debugging and ran my test again. As expected it halted in the debugger on the point where the exception was thrown. As expected it halted in mscorlib.dll, in this case in the System.Reflection.Emit.AssemblyBuilder class in the method GetManifestResourceNames(). This does confirm that it is actually caused by the bug I mentioned earlier, however it doesn’t really help us with a solution yet. The question now is, “why is someone calling this method on a dynamic assembly?”.
Browsing up the call stack makes it very clear that this code is being called from the Entity Framework. In fact it is called from the System.Data.Objects.ObjectContext constructor, but why? Taking a closer look at the call stack there is some indication that it must have something to do with initializing the metadata needed for the Entity Framework. It also reveals that the exception occurred in the System.Data.EntityClient.EntityConnection class in a method called SplitPaths. Looking at the code in that method and the state it was in as the exception occurred actually showed me what caused the problem. In the SplitPaths method there is a string[] called results (what’s in a name, right?) which contained three strings: res://*/Model.csdl, res://*/Model.ssdl and res://*/Model.mdl.
Looks familiar? That’s because these url’s are found in the default connection string for Entity Framework and they should point to the three files that make up the Entity Framework metadata. For some more documentation on that look here.
What was actually happening here was that a dynamic assembly was asked for it’s resources as the Entity Framework code was looking for a metadata file in all the loaded resources, as indicated by it’s connection string. The dynamic assembly that was loaded in this case was the binary for the WCF web service that hosts our DAL. The fix was simple. Just point to the exact assembly by it’s full name in the connection string for each metadata file and it’s fixed. This is how the metadata entry in our connection string looks now (obviously with some name changes):
1: metadata=res://OurApp.Data, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null/OurModel.csdlres://OurApp.Data, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null/OurModel.ssdlres://OurApp.Data, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null/OurModel.msl;
I hope you found this search for this fix as useful as I did and it helps you out. Please leave me a comment if you have any questions.
30-07-2010 EDIT: Added the metadata part of the connection string to make the solution more clear. Thanks to greg-joyal for pointing that out to me.
Posts
