Detect Poor Performing Queries In Entity Framework 6.x

Recently I came upon a post from Rown Miller in which he created a simple interceptor to log poor performing queries or failing queries, which really seems promising to track down those queries. Although there is already an awesome well-known tool, Glimpse, this helps you track down the server processing time and other informational data with a quick setup. It also logs the queries if your ASP.NET application is using Entity Framework. But it’s limited to Web applications. So what about Windows, WPF, and other standalone apps?

I just extended the interceptor class as a library and included the support to introduce a custom logger to write queries on any target.

By introducing an Interface for logging:

/// <summary>
/// Implement this logger for any custom targets where queries should be logged.
/// </summary>
public interface IQueryLogger
{
   void Write(params string[] content);
}

Checkout the original interceptor here. I have tweaked it a little to have a filter for including StackTrace. Here’s the updated class.

public class ExpensiveSqlLoggerInterceptor: DbCommandInterceptor
{
    private readonly IQueryLogger _queryLogger;
    private readonly int _executionMillisecondThreshold;
    private readonly bool _includeStackTrace;


    public ExpensiveSqlLoggerInterceptor(IQueryLogger logger, int executionMillisecondThreshold, bool enableStackTrace = true)
    {
        _queryLogger = logger;
        _executionMillisecondThreshold = executionMillisecondThreshold;
        _includeStackTrace = enableStackTrace;
    }


    public override voidR eaderExecuting(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext)
    {
        Executing(interceptionContext);
        base.ReaderExecuting(command, interceptionContext);
    }


    public override void ReaderExecuted(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext)
    {
        Executed(command, interceptionContext);
        base.ReaderExecuted(command, interceptionContext);
    }


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


    public override void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext < int > interceptionContext)
    {
        Executed(command, interceptionContext);
        base.NonQueryExecuted(command, interceptionContext);
    }


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


    public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext < object > interceptionContext)
    {
        Executed(command, interceptionContext);
        base.ScalarExecuted(command, interceptionContext);
    }


    private void Executing < T > (DbCommandInterceptionContext < T > interceptionContext)
    {
        var timer = new Stopwatch();
        interceptionContext.UserState = timer;
        timer.Start();
    }


    private void Executed < T > (DbCommand command, DbCommandInterceptionContext < T > interceptionContext)
    {
        var timer = (Stopwatch) interceptionContext.UserState;
        timer.Stop();


        if (interceptionContext.Exception != null)
        {
            _queryLogger.Write("FAILED COMMAND",
                interceptionContext.Exception.Message,
                command.CommandText,
                _includeStackTrace ? Environment.StackTrace : string.Empty,
                string.Empty,
                string.Empty);
        }
        elseif(timer.ElapsedMilliseconds >= _executionMillisecondThreshold)
        {
            _queryLogger.Write(
                string.Format("SLOW COMMAND ({0} ms)", timer.ElapsedMilliseconds),
                command.CommandText,
                _includeStackTrace ? Environment.StackTrace : string.Empty,
                string.Empty,
                string.Empty
            );
        }
    }
}

Let's say I want to write to Visual Studio Debug window, simply implement the IQueryLogger interface:

/// <summary>
/// Writes the output to the visual studio output window.
/// </summary>
public class OutputWindowLogger: IQueryLogger
{
    public void Write(params string[] content)
    {
        content.ToList().ForEach(data => System.Diagnostics.Trace.WriteLine(data, "Expensive Query log =>"));
    }
}

A quick setup to use the interceptor is just  to implement the DbConfiguration class and add the interceptor:

public class CustomConfig: DbConfiguration
{
    public CustomConfig()
    {
        this.AddInterceptor(new ExpensiveSqlLoggerInterceptor(new OutputWindowLogger(), 1, false));
    }
}

That’s it. Now you can run your application and look for the debug window with “Expensive Query Log =>”

Here’s the complete source code of EF6Logger library on GitHub.

 

Read more articles on .NET Core:

• What .NET 2015 Is
• .NET CLR Interview Questions and Answers 
• Entity Framework - Database First Approach