Post
Ask Question

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. {   
    6.    void Write(params string[] content);    
    7. }  
    Check out 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.     private readonly IQueryLogger _queryLogger;  
    3.     private readonly int _executionMillisecondThreshold;  
    4.     private readonly bool _includeStackTrace;  
    5.   
    6.     public ExpensiveSqlLoggerInterceptor(IQueryLogger logger, int executionMillisecondThreshold, bool enableStackTrace = true) {  
    7.         _queryLogger = logger;  
    8.         _executionMillisecondThreshold = executionMillisecondThreshold;  
    9.         _includeStackTrace = enableStackTrace;  
    10.     }  
    11.   
    12.     public override voidR eaderExecuting(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext) {  
    13.         Executing(interceptionContext);  
    14.         base.ReaderExecuting(command, interceptionContext);  
    15.     }  
    16.   
    17.     public override void ReaderExecuted(DbCommand command, DbCommandInterceptionContext < DbDataReader > interceptionContext) {  
    18.         Executed(command, interceptionContext);  
    19.         base.ReaderExecuted(command, interceptionContext);  
    20.     }  
    21.   
    22.     public override void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext < int > interceptionContext) {  
    23.         Executing(interceptionContext);  
    24.         base.NonQueryExecuting(command, interceptionContext);  
    25.     }  
    26.   
    27.     public override void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext < int > interceptionContext) {  
    28.         Executed(command, interceptionContext);  
    29.         base.NonQueryExecuted(command, interceptionContext);  
    30.     }  
    31.   
    32.     public override void ScalarExecuting(DbCommand command, DbCommandInterceptionContext < object > interceptionContext) {  
    33.         Executing(interceptionContext);  
    34.         base.ScalarExecuting(command, interceptionContext);  
    35.     }  
    36.   
    37.     public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext < object > interceptionContext) {  
    38.         Executed(command, interceptionContext);  
    39.         base.ScalarExecuted(command, interceptionContext);  
    40.     }  
    41.   
    42.     private void Executing < T > (DbCommandInterceptionContext < T > interceptionContext) {  
    43.         var timer = new Stopwatch();  
    44.         interceptionContext.UserState = timer;  
    45.         timer.Start();  
    46.     }  
    47.   
    48.     private void Executed < T > (DbCommand command, DbCommandInterceptionContext < T > interceptionContext) {  
    49.         var timer = (Stopwatch) interceptionContext.UserState;  
    50.         timer.Stop();  
    51.   
    52.         if (interceptionContext.Exception != null) {  
    53.             _queryLogger.Write("FAILED COMMAND",  
    54.                 interceptionContext.Exception.Message,  
    55.                 command.CommandText,  
    56.                 _includeStackTrace ? Environment.StackTrace : string.Empty,  
    57.                 string.Empty,  
    58.                 string.Empty);  
    59.         } else if (timer.ElapsedMilliseconds >= _executionMillisecondThreshold) {  
    60.             _queryLogger.Write(  
    61.                 string.Format("SLOW COMMAND ({0} ms)", timer.ElapsedMilliseconds),  
    62.                 command.CommandText,  
    63.                 _includeStackTrace ? Environment.StackTrace : string.Empty,  
    64.                 string.Empty,  
    65.                 string.Empty  
    66.             );  
    67.         }  
    68.     }  
    69. } 
    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 the EF6Logger library on GitHub.
     
    Read more articles on .NET Core:


    Similar Articles