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);
}

Check out 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);
} else if (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 the EF6Logger library on GitHub.