Entity Framework Profiler – When .ToTraceString() just isn’t enough!
Recently I spent a fair bit of time poking around the Entity Framework in Reflector (the reason for which will be apparent soon) and whilst I was poking around ObjectQuery, ObjectQuery<T>, ObjectContext and a host of other objects in the framework’s API, I was immediately reminded of the significance of the effort that had gone into providing this tool. I have voiced my opinions in the past when it came to things I felt were lacking in the design aspects of the framework, particularly as they related to the style of working that the current version imposed on me. However, that discussion is based on a ’style’ of working that I wish to apply and not the general purpose application for which the framework was intended. There is nothing stopping me from using NHibernate or any other ORM if I choose to and it’s true that I went to the extent of developing my own lite framework to enable me in pursuing this preferred ’style’ of work with the Entity Framework. The ’style’ to which I refer is DDD and perhaps it’s true that often I don’t practice it with a purist’s heart when it comes to the Entity Framework, however it should be noted that users of this style are most likely in a minority. I don’t recall an outcry when ADO.Net 2.0 was released? Sure, ADO.Net never purported to being an ORM and that’s ok I get the distinction but who said an ORM should be built to keep the practitioners of DDD happy anyway?
As I said, I have pointed out in the past some areas I felt were lacking in the design of the Entity Framework however every story requires to be told in balance, with the good and bad and it should be stated equally when there is praise to be made. I find the Entity Framework an excellent Data Access Technology in general and I hope (and indeed believe) that those like me, who wish to develop in styles that were perhaps not foremost in the EF teams minds initially, will be gradually accommodated in future versions. For example, transparent lazy loading will be available in .NET 4.0 and will be managed by a binary switch in the ObjectContext. Until such time there are other options.
What started all this?
So I got a bit off topic, lets focus on why I was digging around the EF in Reflector. Recently, Ayende’s NHibernate Profiler tool had me wishing for something similar’ish in the Entity Framework space. So to understand better how that might be achieved I began looking deeper into the Entity Framework ‘goo’ to see how feasible, an albeit much more lite weight approach than Ayende’s, might be possible. One initial limitation i chose to impose at the start was that the profiler will not be built (by me) using Microsoft’s profiling API, unless someone can point out to me a completely managed option.
Motivation
It is always a concern that developers who choose to enlist the services of LINQ To Entities or LINQ To SQL might not vigilantly monitor the SQL that those implementations are producing. Developers should never rest on their laurels and become satisfied that their ORM ensures that everything is working ok, as long as the data returned is as expected then there are no problems, we should never assume that our performance is optimal because the ORM will make it so. Furthermore if your using LINQ To Entities, it’s not impossible that what looks to make sense in your LINQ C#/VB code is not making sense as SQL. I recently described a way of working with LinqPad that will allow you to write queries in both the Entity Framework and LINQ To SQL however it will only produce the TSQL in it’s viewer when using LINQ To SQL. Some other tools / methods on offer to monitor provider specific generated SQL are the following:
- LINQ To SQL
- DebuggerWriter by Chris Vandermotten
- LINQ To SQL Debug Visualizer.
- Entity Framework
- Julie Lerman’s Logging Class
And so, to help myself in this very endeavour I set out to build an Entity Framework Profiler to try to address the dislocated nature of having to switch between viewing output from .ToTraceString(), SQL Profiler and LINQPAD.
How does it work?
Using WCF the Profiler listens for messages at the localhost (loopback) address. The messages handled by it’s service, contain meta data and the SQL query text sent to the database by the Entity Framework. So how does the Entity Framework know how to send messages? ASPECT oriented code weaving is what creates this illusion for us. I had previously used PostSharp to help develop a framework that unifies the both Lazy and Eager loading, provides Specifications for dynamic querying and includes a generic repository. After having that positive experience with PostSharp It was clear that it would again be useful in the design for the Profiler. The profiler relies on Entity Framework consumers to use a custom PostSharp attribute to weave code into the ObjectQuery<T> implementations in their Entity Models (.edmx files). Here listed are the more pertinent parts of the code found in the EntityFrameworkProfilingAttribute class:
private EntityInterceptMessage BuildMessageFromMetaData (MethodExecutionEventArgs eventArgs, ref TimeSpan time_taken, ObjectQuery q, ObjectContext ctx) { var query = from meta in ctx.MetadataWorkspace. GetEntityContainer(ctx.DefaultContainerName, DataSpace.CSpace).BaseEntitySets let fields = from f in meta.ElementType.Members.ToList() select new { FieldName = f.Name, FieldType = f.TypeUsage.EdmType.Name } where meta.BuiltInTypeKind == BuiltInTypeKind.EntitySet && meta.Name == eventArgs.Method.Name.Replace(“get_”, “”) select new { EntitySetName = meta.Name, EntityName = meta.ElementType.Name, Members = fields }; EntityInterceptMessage entity_message = new EntityInterceptMessage() { SqlQueryText = q.ToTraceString(), ProcessID = AppDomain.CurrentDomain.Id.ToString(), ThreadID = Thread.CurrentThread.ManagedThreadId.ToString(), EntityModelName = ctx.DefaultContainerName, Succeeded = eventArgs.Exception == null ? true : false, ExecutionTime = string.Format(“{0} Ms {1} Ticks”, time_taken.TotalMilliseconds, time_taken.Ticks), MetaData = new EntityInterceptMessage.EntityInterceptMeta() { ContextName = ctx.DefaultContainerName, EntitySetName = query.First().EntitySetName, EntityTypeName = query.First().EntityName, EntityTypeFields = (from f in query.First().Members select new EntityInterceptMessage.EntityFieldNameTypePair() { FieldName = f.FieldName, FieldTypeName = f.FieldType }).ToList() } }; return entity_message; }
The Service Code:
private void CreateAndSendMessageToProfiler (EntityInterceptMessage entity_message) { EndpointAddress address = new EndpointAddress (“net.tcp://localhost:9002/EntityProfilerSvc”); var binding = new NetTcpBinding { SendTimeout = new TimeSpan(0, 10, 0) }; ChannelFactory<IProfilerService> factory = new ChannelFactory<IProfilerService>(binding, address); var channel = factory.CreateChannel(); XmlReader reader = MessageSerializer.SerializeMessage(entity_message); //Create the Message with the serialized data //embedded into its body var msg = chans.Message.CreateMessage( binding.MessageVersion, “urn:IProfilerService-Send”, reader); channel.Send(msg); factory.Close(); }
If you dig around in Reflector you can see the code woven into by PostSharp.
The biggest problem I have with this approach is that Entity SQL is not catered for. I would have preferred to use a true Profiling API like the Microsoft one, however the requirement in using unmanaged code left me to bypass that option for now. I very well might re-work the entire application using that API when I get more time to look more deeply into it, but for now it was more important to me to get an alternative going quickly.
What information does the Profiler provide?
The single most important data to report on was always going to be the SQL Query text created by an ObjectQuery<T>. Along with this I have packaged up the execution time for the query (from the managed codes perspective not the database), the fields involved in the query and the process and thread ID’s that execute each query.
What’s Next?
The next thing to add is definitely going to be persistence to disk, making it possible to review query data from previous sessions. Once that’s in place I am going to build an IronRuby console into the application so you can write REPL scripts against your Entity Framework Entity Models and profile the results right there in the profiler – instant Entity Framework gratification! And finally to create a Visual Studio template for the EntityFrameworkProfilingAttribute class so it’s easy to add it to your own libraries that include Entity Models. The code box for the SQL Text is licensed under the code project open license and usage of the Profiler requires accepting this license. As I have said all along, suggestions are welcome. To see how this all works, you can get the code here and just run the tests and you will see the messages appear in the Profiler.
No comments








