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
romiller.com 