Wednesday, January 5, 2011

Poor man’s Entity Framework profiler

We recently added the ability to trace the Sql statements being executed by an EF query.   This is a companion to the code that was added long ago to the Enterprise Library to do the same thing.  In the case of the Enterprise Library we customized the library itself to trace the Sql before being executed.  This has been useful numerous times for troubleshooting performance issues.  In those cases its been very handy be able to see all the Sql being executed, to know which queries are taking the longest and/or called the most in a given context. 

However, our move to EF had left gaps in this tracing, reducing our visibility into what was was being called and how often.  EF, because it generates its Sql, also reduced our visibility into the Sql itself.  While troubleshooting performance problems in our poor performing “Customer View” page we had need to add EF tracing in order to get the full performance picture.

In our case we are essentially only using two methods that cause EF queries to execute, ToList(), FirstOrDefault().  Therefore, I created two IQueryable extension methods, ExecuteToList(), ExecuteFirstOrDefault(), and replaced all calls to the former with the latter.  The two Execute* methods are simply wrappers that delegate to their counterparts.  The advantage being that within the wrapper methods we can inject tracing logic.

        public static TEntity ExecuteFirstOrDefault<TEntity>(this IQueryable<TEntity> query)
{
DebugQuery(query);
var executeFirstOrDefault = query.FirstOrDefault();
Debug.WriteLine("**********End************");
return executeFirstOrDefault;
}

public static List<TEntity> ExecuteToList<TEntity>(this IQueryable<TEntity> query)
{
DebugQuery(query);
var executeToList = query.ToList();
Debug.WriteLine("**********End************");
return executeToList;
}

private static void DebugQuery<TEntity>(IQueryable<TEntity> query)
{
#if DEBUG

Debug.WriteLine("**********Begin************");
var stackTrace = new StackTrace();
var method = stackTrace.GetFrame(2).GetMethod();
Debug.WriteLine(string.Format("{0}.{1}", method.DeclaringType.Name, method.Name));
Debug.WriteLine(query.ToTraceString());
#endif

}

The moral of this story is that if you want tracing you now have to make sure you’re using the extension methods rather than the base methods.

3 comments:

  1. I used that tactic in the first version of my Programming EF book. I still like to contain my execution like this to trap errors etc consistently but for profiling there are now some great options (including EFTracing provider which is free). Check out this MSDN Data Points column on EF Query Profiling: http://msdn.microsoft.com/en-us/magazine/gg490349.aspx

    hth

    ReplyDelete
  2. Thanks Julie. I actually saw read that article after I had implemented this simple version. I intend to revisit it.

    ReplyDelete
  3. I use Linq Insight for executing and profiling linq queries. If I need to work with Entity Framework applications I use built in Entity Framework profiler - a great tool from Devart.
    More info here: http://www.devart.com/linqinsight/entity-framework-profiler.html

    ReplyDelete