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:

  1. /// <summary>  
  2. /// Implement this logger for any custom targets where queries should be logged.  
  3. /// </summary>  
  4. public interface IQueryLogger  
  5.    void Write(params string[] content);  
  6. }  
Checkout the original interceptor here. I have tweaked it a little to have a filter for including StackTrace. Here’s the updated class.
  1. public class ExpensiveSqlLoggerInterceptor: DbCommandInterceptor  
  2. {  
  3.     private readonly IQueryLogger _queryLogger;  
  4.     private readonly int _executionMillisecondThreshold;  
  5.     private readonly bool _includeStackTrace;  
  6.   
  7.   
  8.     public ExpensiveSqlLoggerInterceptor(IQueryLogger logger, int executionMillisecondThreshold, bool enableStackTrace = true)  
  9.     {  
  10.         _queryLogger = logger;  
  11.         _executionMillisecondThreshold = executionMillisecondThreshold;  
  12.         _includeStackTrace = enableStackTrace;  
  13.     }  
  14.   
  15.   
  16.     public override voidR eaderExecuting(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext)  
  17.     {  
  18.         Executing(interceptionContext);  
  19.         base.ReaderExecuting(command, interceptionContext);  
  20.     }  
  21.   
  22.   
  23.     public override void ReaderExecuted(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext)  
  24.     {  
  25.         Executed(command, interceptionContext);  
  26.         base.ReaderExecuted(command, interceptionContext);  
  27.     }  
  28.   
  29.   
  30.     public override void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext < int > interceptionContext)  
  31.     {  
  32.         Executing(interceptionContext);  
  33.         base.NonQueryExecuting(command, interceptionContext);  
  34.     }  
  35.   
  36.   
  37.     public override void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext < int > interceptionContext)  
  38.     {  
  39.         Executed(command, interceptionContext);  
  40.         base.NonQueryExecuted(command, interceptionContext);  
  41.     }  
  42.   
  43.   
  44.     public override void ScalarExecuting(DbCommand command, DbCommandInterceptionContext < object > interceptionContext)  
  45.     {  
  46.         Executing(interceptionContext);  
  47.         base.ScalarExecuting(command, interceptionContext);  
  48.     }  
  49.   
  50.   
  51.     public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext < object > interceptionContext)  
  52.     {  
  53.         Executed(command, interceptionContext);  
  54.         base.ScalarExecuted(command, interceptionContext);  
  55.     }  
  56.   
  57.   
  58.     private void Executing < T > (DbCommandInterceptionContext < T > interceptionContext)  
  59.     {  
  60.         var timer = new Stopwatch();  
  61.         interceptionContext.UserState = timer;  
  62.         timer.Start();  
  63.     }  
  64.   
  65.   
  66.     private void Executed < T > (DbCommand command, DbCommandInterceptionContext < T > interceptionContext)  
  67.     {  
  68.         var timer = (Stopwatch) interceptionContext.UserState;  
  69.         timer.Stop();  
  70.   
  71.   
  72.         if (interceptionContext.Exception != null)  
  73.         {  
  74.             _queryLogger.Write("FAILED COMMAND",  
  75.                 interceptionContext.Exception.Message,  
  76.                 command.CommandText,  
  77.                 _includeStackTrace ? Environment.StackTrace : string.Empty,  
  78.                 string.Empty,  
  79.                 string.Empty);  
  80.         }  
  81.         elseif(timer.ElapsedMilliseconds >= _executionMillisecondThreshold)  
  82.         {  
  83.             _queryLogger.Write(  
  84.                 string.Format("SLOW COMMAND ({0} ms)", timer.ElapsedMilliseconds),  
  85.                 command.CommandText,  
  86.                 _includeStackTrace ? Environment.StackTrace : string.Empty,  
  87.                 string.Empty,  
  88.                 string.Empty  
  89.             );  
  90.         }  
  91.     }  
  92. }  
Let's say I want to write to Visual Studio Debug window, simply implement the IQueryLogger interface:
  1. /// <summary>  
  2. /// Writes the output to the visual studio output window.  
  3. /// </summary>  
  4. public class OutputWindowLogger: IQueryLogger  
  5. {  
  6.     public void Write(params string[] content)  
  7.     {  
  8.         content.ToList().ForEach(data => System.Diagnostics.Trace.WriteLine(data, "Expensive Query log =>"));  
  9.     }  
  10. }  
A quick setup to use the interceptor is just  to implement the DbConfiguration class and add the interceptor:
  1. public class CustomConfig: DbConfiguration  
  2. {  
  3.     public CustomConfig()  
  4.     {  
  5.         this.AddInterceptor(new ExpensiveSqlLoggerInterceptor(new OutputWindowLogger(), 1, false));  
  6.     }  
  7. }  
That’s it. Now you can run your application and look for the debug window with “Expensive Query Log =>

Expensive Query Log

Here’s the complete source code of EF6Logger library on GitHub.
 
Read more articles on .NET Core: