EF6.x Correlating Poor Performing SQL to Application Code

Posted on February 11, 2016. Filed under: Entity Framework | Tags: , , , , , , , , |

When using an O/RM, poor performing SQL statements are often not discovered until you (or your DBA) find that a particular query is slowing down your database server. At this point, it becomes hard to identify which piece of application code is causing that SQL to be executed.

 

An interceptor to log slow/failed SQL

In EF6.0.0 we introduced interceptors, which allow you to get into the pipeline just before, and just after, a query/command is sent to the database.

Here is an interceptor that detects queries/commands that either failed, or exceeded a chosen threshold for execution time. In addition to the query being executed, it logs the call stack. This allows us to identify which piece of our application code initiated the database operation.

This example writes to a log file, but you can log the information to wherever needed.

public class PoorSqlLogger : DbCommandInterceptor
{
    private readonly string _logFile;
    private readonly int _executionMillisecondThreshold;

    public PoorSqlLogger(string logFile, int executionMillisecondThreshold)
    {
        _logFile = logFile;
        _executionMillisecondThreshold = executionMillisecondThreshold;
    }

    public override void ReaderExecuting(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)
        {
            File.AppendAllLines(
                _logFile,
                new string[]
                {
                "FAILED COMMAND",
                interceptionContext.Exception.Message,
                command.CommandText,
                Environment.StackTrace,
                string.Empty,
                string.Empty,
                });
        }
        else if (timer.ElapsedMilliseconds >= _executionMillisecondThreshold)
        {
            File.AppendAllLines(
                _logFile,
                new string[]
                {
                $"SLOW COMMAND ({timer.ElapsedMilliseconds}ms)",
                command.CommandText,
                Environment.StackTrace,
                string.Empty,
                string.Empty,
                });
        }
    }
}

 

Registering the interceptor

The easiest way to get our interceptor into the pipeline is with code-based configuration. Simply create a class that derives from DbConfiguration in the same assembly as your context.

public class MyConfig : DbConfiguration
{
    public MyConfig()
    {
        this.AddInterceptor(new PoorSqlLogger(@"C:\temp\log.txt", 1));
    }
}

 

You can also register interceptors in you app/web.config file. This allows you to enable/disable the interceptors without recompiling your application.

 

Sample output

Here is some sample output. Note for this run the threshold for slow queries was set very low, for demonstration purposes (hence the 2ms query is flagged as a slow query). You’ll see we get full stack information that tells us which part of our application initiated the query/command. If symbols are available, then we also get line numbers (as shown in this example).

SLOW COMMAND (2ms)
SELECT 
    [Extent1].[BlogId] AS [BlogId], 
    [Extent1].[Url] AS [Url]
    FROM [dbo].[Blogs] AS [Extent1]
    WHERE [Extent1].[Url] LIKE N'%msdn%'
    ORDER BY [Extent1].[Url] ASC
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at EF6.BadCommandLogger.Executed[T](DbCommand command, DbCommandInterceptionContext`1 interceptionContext) in C:\Demo\Program.cs:line 149
   at EF6.BadCommandLogger.ReaderExecuted(DbCommand command, DbCommandInterceptionContext`1 interceptionContext) in C:\Demo\Program.cs:line 93
   at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.<Reader>b__e(IDbCommandInterceptor i, DbCommand t, DbCommandInterceptionContext`1 c)
   at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch[TTarget,TInterceptionContext,TResult](TTarget target, Func`3 operation, TInterceptionContext interceptionContext, Action`3 executing, Action`3 executed)
   at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.Reader(DbCommand command, DbCommandInterceptionContext interceptionContext)
   at System.Data.Entity.Internal.InterceptableDbCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.Entity.Core.Objects.Internal.ObjectQueryExecutionPlan.Execute[TResultType](ObjectContext context, ObjectParameterCollection parameterValues)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.<>c__DisplayClass7.<GetResults>b__6()
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteInTransaction[T](Func`1 func, IDbExecutionStrategy executionStrategy, Boolean startLocalTransaction, Boolean releaseConnectionOnSuccess)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.<>c__DisplayClass7.<GetResults>b__5()
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute[TResult](Func`1 operation)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.GetResults(Nullable`1 forMergeOption)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.<System.Collections.Generic.IEnumerable<T>.GetEnumerator>b__0()
   at System.Data.Entity.Internal.LazyEnumerator`1.MoveNext()
   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at EF6.Program.GetMsdnBlogs() in C:\Demo\Program.cs:line 24
   at EF6.Program.Main(String[] args) in C:\Demo\Program.cs:line 16


FAILED COMMAND
Invalid object name 'dbo.wrong_table'.
SELECT * FROM dbo.wrong_table
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at EF6.BadCommandLogger.Executed[T](DbCommand command, DbCommandInterceptionContext`1 interceptionContext) in C:\Demo\Program.cs:line 135
   at EF6.BadCommandLogger.ReaderExecuted(DbCommand command, DbCommandInterceptionContext`1 interceptionContext) in C:\Demo\Program.cs:line 93
   at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.<Reader>b__e(IDbCommandInterceptor i, DbCommand t, DbCommandInterceptionContext`1 c)
   at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch[TTarget,TInterceptionContext,TResult](TTarget target, Func`3 operation, TInterceptionContext interceptionContext, Action`3 executing, Action`3 executed)
   at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.Reader(DbCommand command, DbCommandInterceptionContext interceptionContext)
   at System.Data.Entity.Internal.InterceptableDbCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteStoreQueryInternal[TElement](String commandText, String entitySetName, ExecutionOptions executionOptions, Object[] parameters)
   at System.Data.Entity.Core.Objects.ObjectContext.<>c__DisplayClass65`1.<ExecuteStoreQueryReliably>b__64()
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteInTransaction[T](Func`1 func, IDbExecutionStrategy executionStrategy, Boolean startLocalTransaction, Boolean releaseConnectionOnSuccess)
   at System.Data.Entity.Core.Objects.ObjectContext.<>c__DisplayClass65`1.<ExecuteStoreQueryReliably>b__63()
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute[TResult](Func`1 operation)
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteStoreQueryReliably[TElement](String commandText, String entitySetName, ExecutionOptions executionOptions, Object[] parameters)
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteStoreQuery[TElement](String commandText, String entitySetName, ExecutionOptions executionOptions, Object[] parameters)
   at System.Data.Entity.Internal.Linq.InternalSet`1.<>c__DisplayClass11.<ExecuteSqlQuery>b__10()
   at System.Data.Entity.Internal.LazyEnumerator`1.MoveNext()
   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at EF6.Program.GetBlogs() in C:\Demo\Program.cs:line 35
   at EF6.Program.Main(String[] args) in C:\Demo\Program.cs:line 17

 

Full source listing

Here is a Gist with a full source listing for a console application that shows the interceptor in action.


Read Full Post | Make a Comment ( 4 so far )

Recently on RoMiller.com…

EF6.1 Get Mapping Between Properties and Columns

Posted on August 5, 2015. Filed under: Entity Framework, Visual Studio | Tags: , , , , , , |

EF6.1–Workaround Trailing Blanks Issue in String Joins

Posted on October 20, 2014. Filed under: Entity Framework | Tags: , , , , , |

EF6.1 Getting Key Properties for an Entity

Posted on October 7, 2014. Filed under: Entity Framework | Tags: , , , |

Reducing Code First Database Chatter

Posted on June 10, 2014. Filed under: Entity Framework, Visual Studio | Tags: , , , , , |

EF6.1 Mapping Between Types & Tables

Posted on April 8, 2014. Filed under: Entity Framework | Tags: , , , , , , |

EF6/6.1 Level 300-400 Talk-in-a-Box

Posted on February 21, 2014. Filed under: Entity Framework, Visual Studio | Tags: , , , , , |

EF6 Level 100-200 Talk-in-a-Box

Posted on February 11, 2014. Filed under: Entity Framework, Visual Studio | Tags: , , , , |

EF Code First Mapping Between Types & Tables

Posted on September 24, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , |

EF5 & EF6 on VS Toolbox (Source Code Included)

Posted on August 27, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , , , , , , |

EF6 Suspendable Execution Strategy

Posted on August 19, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , , , |

TechEd 2013 Talks & Source Code

Posted on June 10, 2013. Filed under: ASP.NET, Entity Framework, Visual Studio | Tags: , , , , |

How to Drop a Database from Visual Studio 2012

Posted on May 17, 2013. Filed under: Visual Studio | Tags: , , , |

Running EF T4 Code Generation Templates from Command Line

Posted on May 15, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , |

EF6: Switching Identity On/Off with a Custom Migration Operation

Posted on April 30, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , |

Processor named ‘T4VSHost’ could not be found for the directive named ‘CleanupBehavior’

Posted on March 21, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , , |

EF6: Writing Your Own Code First Migration Operations

Posted on February 27, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , , |

Extending And Customizing Code First Models – Part 2 of 2

Posted on February 15, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , |

Extending and Customizing Code First Models – Part 1 of 2

Posted on February 5, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , |

EF6 Code First: Configuring Unmapped Base Types

Posted on January 29, 2013. Filed under: Entity Framework, Visual Studio | Tags: , , , , |

    About

    Rowan works as a Program Manager for the ADO.NET Entity Framework team at Microsoft. He speaks at technical conferences and blogs at romiller.com. Rowan lives in Seattle, Washington with his wife Athalie. Prior to moving to the US he resided in the small state of Tasmania in Australia. Outside of technology Rowan's passions include snowboarding, mountain biking, horse riding, rock climbing and pretty much anything else that involves being active. The primary focus of his life, however, is to follow Jesus.

    RSS

    Subscribe Via RSS

    • Subscribe with Bloglines
    • Add your feed to Newsburst from CNET News.com
    • Subscribe in Google Reader
    • Add to My Yahoo!
    • Subscribe in NewsGator Online
    • The latest comments to all posts in RSS

    Meta

Liked it here?
Why not try sites on the blogroll...

Follow

Get every new post delivered to your Inbox.

Join 228 other followers