Sql query performance monitoring with EF6 through interception

Lately I've been building a web application against a database that I don't have full control over which is used by a variety of other internal applications. If something were to affect the performance of my app (such as a slow database query) I'd like to know before my users start to complain. To that end, I've built out some very basic always-on production monitoring/instrumentation. For example, I set up a Http Module to monitor response times on all Http requests, and log the ones that fall outside of a given threshold.

I've been using NLog, through the Common.Logging interface to handle this sort of thing. I have NLog configured to email me a log dump whenever an error or warning occurs. If I can just log a warning when a sql query takes too long, the rest of the process (logging, emailing, etc) is taken care of.

When I first started looking into it, I was looking at the new DbContext.Database.Log property in Entity Framework 6. I could set it to any action that takes a string, intercept the messages, and parse out the occasional log message that contained the query execution time. This was admittedly a bit messy, but it worked.

I did a little more research and discovered what I really needed... database interception. In particular, this article laid out a simple example of database interception code. However it didn't show any way to actually measure query execution time. I decided to figure out how the EF logger was doing it. After looking at some stack traces and poking around in JustDecompile, I found the System.Data.Entity.Infrastructure.Interception.DatabaseLogFormatter class. This is the class that actually generates the messages sent through the Database.Log action. It works as a database interceptor, and just implements a simple timer that starts and stops with each SQL command that passes through it. Armed with this information, I had enough to build up a proper sql monitoring class for EF6 that logs slow queries and also sql errors:

	System.Data.Entity.Infrastructure.Interception.DbInterception.Add(new SqlMonitorInterceptor());

view raw ApplicationStartup.cs hosted with ❤ by GitHub

	using Common.Logging;
	using System;
	using System.Configuration;
	using System.Data.Common;
	using System.Data.Entity.Infrastructure.Interception;
	using System.Diagnostics;
	namespace MySampleApp.Data.Sql
	{
	public class SqlMonitorInterceptor : IDbCommandInterceptor
	{
	private static readonly ILog logger = LogManager.GetCurrentClassLogger();
	private static readonly int sqlWarningThresholdMs = int.Parse(ConfigurationManager.AppSettings["sqlPerformance_warningThresholdMilliseconds"]);
	private readonly Stopwatch _stopwatch = new Stopwatch();
	public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
	{
	CommandExecuting();
	}
	public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
	{
	CommandExecuted(command, interceptionContext);
	}
	public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
	{
	CommandExecuting();
	}
	public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
	{
	CommandExecuted(command, interceptionContext);
	}
	public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
	{
	CommandExecuting();
	}
	public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
	{
	CommandExecuted(command, interceptionContext);
	}
	private void CommandExecuting() {
	_stopwatch.Restart();
	}
	private void CommandExecuted<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
	{
	_stopwatch.Stop();
	LogIfError(command, interceptionContext);
	LogIfTooSlow(command, _stopwatch.Elapsed);
	}
	private void LogIfError<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
	{
	if (interceptionContext.Exception != null)
	{
	logger.ErrorFormat("Command {0} failed with exception {1}",
	command.CommandText, interceptionContext.Exception);
	}
	}
	private void LogIfTooSlow(DbCommand command, TimeSpan completionTime)
	{
	if (completionTime.TotalMilliseconds > sqlWarningThresholdMs)
	{
	logger.WarnFormat("Query time ({0}ms) exceeded the threshold of {1}ms. Command: \"{2}\"",
	completionTime.TotalMilliseconds, sqlWarningThresholdMs, command.CommandText);
	}
	}
	}
	}

view raw SqlMonitorInterceptor.cs hosted with ❤ by GitHub

	<configuration>
	<appSettings>
	<add key="sqlPerformance_warningThresholdMilliseconds" value="1000"/>
	</appSettings>
	</configuration>

view raw web.config hosted with ❤ by GitHub