Profiling Entity Framework

Home / Profiling Entity Framework

Profiling a ‘black box’ framework to see exactly how it works and behaves can be edifying. It can also lead to better optimizations/usage of the framework. In my case, it helped diminish the mistrust of Entity Framework.

There are tools like Rhinomocks EF Profiler which allow for inspecting the ObjectContext of Entity Framework. However, if you don’t want to buy additional tools, you can effectively write your own.


With EF 6.x, the DbCommandInterceptor was introduced. This handy mechanism lets you intercept the EF execution pipeline and view the SQL commands, Context, and other facets of EF just prior to execution. I used this mechanism to time all queries and log the results/commands to log4net. The method names in the DbCommandInterceptor are pretty self-explanatory, so I won’t belabor the point. Here’s the code:

using System;
using System.Data.Common;
using System.Data.Entity.Infrastructure.Interception;
using System.Diagnostics;
using System.Linq;

using log4net;

namespace MyApp
{
    /// <summary>
    /// Provides an interceptor to monitor EF commands and log via log4net
    /// </summary>
    public class CommandInterceptor : DbCommandInterceptor
    {
        private ILog _logger;
        private readonly Stopwatch _stopwatch = new Stopwatch();

        public CommandInterceptor(ILog logger)
        {
            _logger = logger;
        }

        [ThreadStatic]
        public static bool LogEntityStatsToDatabase = true;

        public override void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            base.ScalarExecuting(command, interceptionContext);
            _stopwatch.Restart();
        }

        public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            _stopwatch.Stop();
            if (interceptionContext.Exception != null)
            {
                Trace.TraceInformation("Error executing command: {0}", command.CommandText);
                if (LogEntityStatsToDatabase)
                {
                    _logger.Error(string.Format("Error executing command: {0}", command.CommandText), interceptionContext.Exception);
                }
            }
            else
            {
                Trace.TraceInformation("ScalarExecuted: {0}, Elapsed: {1}", command.CommandText, _stopwatch.Elapsed);
                if (LogEntityStatsToDatabase)
                {
                    _logger.DebugFormat("ScalarExecuted.  Elapsed: {0}, Command: {1}", _stopwatch.Elapsed, command.CommandText);
                }
            }
            base.ScalarExecuted(command, interceptionContext);
        }

        public override void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            base.NonQueryExecuting(command, interceptionContext);
            _stopwatch.Restart();
        }

        public override void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
        {
            _stopwatch.Stop();
            if (interceptionContext.Exception != null)
            {
                Trace.TraceInformation("Error executing command: {0}", command.CommandText);
                if (LogEntityStatsToDatabase)
                {
                    _logger.Error(string.Format("Error executing command: {0}", command.CommandText), interceptionContext.Exception);
                }
            }
            else
            {
                Trace.TraceInformation("NonQueryExecuted: {0}, Elapsed: {1}", command.CommandText, _stopwatch.Elapsed);
                if (LogEntityStatsToDatabase)
                {
                    _logger.DebugFormat("NonQueryExecuted.  Elapsed: {0}, Command: {1}", _stopwatch.Elapsed, command.CommandText);
                }
            }
            base.NonQueryExecuted(command, interceptionContext);
        }

        public override void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            base.ReaderExecuting(command, interceptionContext);
            _stopwatch.Restart();
        }

        public override void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            _stopwatch.Stop();
            if (interceptionContext.Exception != null)
            {
                Trace.TraceInformation("Error executing command: {0}", command.CommandText);
                if (LogEntityStatsToDatabase)
                {
                    _logger.Error(string.Format("Error executing command: {0}", command.CommandText), interceptionContext.Exception);
                }
            }
            else
            {
                Trace.TraceInformation("ReaderExecuted: {0}, Elapsed: {1}", command.CommandText, _stopwatch.Elapsed);
                if (LogEntityStatsToDatabase)
                {
                    _logger.DebugFormat("ReaderExecuted.  Elapsed: {0}, Command: {1}", _stopwatch.Elapsed, command.CommandText);
                }
            }
            base.ReaderExecuted(command, interceptionContext);
        }
    }
}

And somewhere in our app, we have to add the interceptor:

// Add an EF interceptor
DbInterception.Add(new CommandInterceptor(logger));

Since I mostly write Web apps using Ninject, I usually do all of this in my NinjectWebCommand start-up file by attaching ILog and CommandInterceptor “ToSelf,” then then getting an instance via the dependency resolver’s GetService method.

Well, that’s pretty much all there is to command interception from a profiling perspective. One can go back to their log4net logging and view all executed queries whether they are Readers, Scalars, or commands (NonQuery).

The only downside I have found to this approach is that the parameters’ values being passed to the query will not be present. IE – you’ll see the parameters like @p_linq_xxxx, but not the values. Wouldn’t it be nice to see the values that are being passed along with the query? I think so. This would allow one to pull the query out of the log and actually run it directly.

This is a little more difficult, and not really possible with the DbCommandInterceptor. All of the queries presented in the DbCommandInterceptor are text command strings. Additionally, the diagnostic method in EF, ToTraceString(), doesn’t provide us with populated parameter values either.

Fortunately, we can take an IQueryable and cast it to DbQuery to facilitate getting the fully qualified query with parameter values. Once it is cast to a DbQuery, we can access the internal / private members in the DbQuery that contain the values and extract these. Then, we cast the DbQuery as an ObjectQuery to call EF’s ToTraceString() to get the Command text, and then insert the values into the Command text. (phew!)

I use this technique beyond profiling too. It’s very useful in a recent system I worked on that allows the end user to create and save queries for later execution through a SQL job. Here are the extension methods:

/// <summary>
/// Helper method to retrieve the fully executable SQL from a DbQuery<T>.
/// </summary>
/// <typeparam name="T"></typeparam>
/// <param name="query"></param>
/// <returns></returns>
public static string ToTraceString<T>(this DbQuery<T> query, bool insertParamsIntoSql = true)
{
    var internalQueryField = query.GetType().GetFields(BindingFlags.NonPublic | BindingFlags.Instance).Where(f => f.Name.Equals("_internalQuery")).FirstOrDefault();
    var internalQuery = internalQueryField.GetValue(query);
    var objectQueryField = internalQuery.GetType().GetFields(BindingFlags.NonPublic | BindingFlags.Instance).Where(f => f.Name.Equals("_objectQuery")).FirstOrDefault();
    var objectQuery = objectQueryField.GetValue(internalQuery) as ObjectQuery<T>;
    return objectQuery.ToTraceStringWithParameters();
}

public static string ToTraceStringWithParameters<T>(this ObjectQuery<T> query, bool insertParamsIntoSql = true)
{
    string traceString = query.ToTraceString();

    if (insertParamsIntoSql)
    {
        foreach (var parameter in query.Parameters)
        {
            traceString = traceString.Replace(string.Format("@{0}", parameter.Name), string.Format("'{0}'", parameter.Value));
        }
    }
    else
    {
        traceString += "\n";
        foreach (var parameter in query.Parameters)
        {
            traceString += parameter.Name + " [" + parameter.ParameterType.FullName + "] = " + parameter.Value + "\n";
        }
    }
    return traceString;
}

To use this code, I would just create an IQueryable, and then call the extension method:

var query = myRepository.Get(x => x.Name.Contains("somestring"));
var queryCommand = (query as DbQuery<MyEntity>).ToTraceString();

And there you have it. We could log that ‘queryCommand’ and run it directly in SSMS or some other SQL tool.

With EF 6.x, we have a lot more hooks/methods to profile and ensure that our applications are running well and generating good queries. We can also placate those who don’t like EF or simply have a ‘show me’ mindset. All in all, it’s win-win.

Leave a Reply