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:

No comments:

Post a Comment

Note: Only a member of this blog may post a comment.