Using Entity Framework Core Interceptors to log SQL queries

Since version 3 Entity Framework Core has supported Interceptors. The interception API allows developers to easily intercept and examine and if desired overide low level DB operations such as connections being opened, transactions being committed and CRUD commands being executed. Interceptors have existed for a long time in NHibernate and are available in Entity Framework 6, so finally having them in EF Core is great. There are three kinds of Interceptors available in EF Core.

1. Command Interceptors – which are on the level of SQL statements
2. Transaction Interceptors – which are on the level of SQL transactions
3. Connection Interceptors – which are on the level of SQL connections

Entity Framework Core command Interceptors

This post will be looking at the command interception API only but usage is very similiar for all three. Command interception requires the following steps:

1. Creating a subclass of the abstract DbCommandInterceptor class in EF.
2. Overiding any methods which you want to ‘hook’ into.
3. Registering your subclass with your DBContext.

The class structure of DbCommandInterceptor is below (note this is a of 3.1.3 as there have been some method changes since EF Core 3.0). You can see the class is abstract and all methods are virtual meaning have to subclass it but can overide only whatever methods are relevant to your use cases.

One of the most useful methods to overide is ReaderExecuted which despite its name actually fires for inserts, updates, deletes (and selects of course) when SaveChanges() is called. This is because the SQL that EF generates for inserts often returns DB generated values such as ints (identity) or GUIDs (NewId/NewSequentialId), while both updates and deletes return the number of rows affected. Inserts with no DB generated columns might fire NonQueryExecuted instead but I’ve not confirmed this.

Logging SQL query text and duration time by overiding ReaderExecuted

Below I’ve created a new class LogSQLQueriesInterceptor which subclasses DbCommandInterceptor and overrides ReaderExecuted to log details about SQL queries. After I’ve logged the query details I call the base ReaderExecuted class so flow can return to EF as normal. Information available in ReaderExecuted includes connection details, the current DbContext as well as information about the actual query ran such as duration in milliseconds, the query text and the query parameters if any.

Final step is to register the new Interceptor with the DbContext your using. I re-scaffold (I don’t use migrations) a lot so I subclass the auto generated DbContext and put the registering of interceptors or other custom code in the subclass so I don’t have to re-do them each time I change my DB schema.

The final output looks like below. This kind of information can be very useful to debug performance issues particularly as the queries are timestamped so you can investigate your spikes which might happen at different times of the day depending on your business.