Showing posts with label Performance. Show all posts
Showing posts with label Performance. Show all posts

Wednesday, September 24, 2014

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: