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.

Entity framework core interceptors - DBCommandInterceptor

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.

Entity Framework core interceptors - registering a new interceptor

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.

Run Scaffold DBContext without overwriting custom code in Entity Framework core.

I prefer to use DB first approach with Entity framework as many do.  In this scenario when the underlying DB schema has changed I just re-scaffold everything by running dotnet ef Scaffold-DbContext with the -force parameter set. When set this parameter causes Entity Framework to overwrite existing files which is want you want as you need your DBContext and model classes to be updated to take account of your new column, table etc. What you don’t want is to lose any custom code you may have had in these classes each time you re-generate the code from your DB. Simple solution here is to use partial classes and/or inheritance.

As an example below.. I often want to see the SQL which EF is generating and in core we can set this up in the OnConfiguring method in the DBContext class. This class will get rebuilt every time you scaffold so you can just inherit from it and then instantiate and use the static non autogenerated one in your app.

Another example might be that you want to have derived properties which are based on one or more properties in one of your auto-generated model classes. Again if you put these directly into the auto-generated model classes you will have to re-do them every time you re-scaffold. In this instance we can use partial classes. Below we see first the auto-generated Students class and then second a manually created partial class which adds a property called FullName. As long as both are in the same namespace .net will put them together.

Generating sequential GUIDs which sort correctly in SQL Server in .net

Using a non sequential GUID in either a clustered or non clustered index is not ideal from a performance point of view as non sequential GUIDs are not ever-increasing (like an identity int) so get inserted into the middle of the index rather than the end resulting in increased logical fragmentation and decreased performance.

If you really can’t switch from a GUID to an identity int (to save space and fragmentation) and you must use a GUID in an index, to mitigate against the performance problems ensure it is sequential and ever-increasing. SQL Server allows you to do this by setting a default constraint on uniqueidentifier columns which calls the NEWSEQUENTIALID() method. This method creates a GUID that is greater than any GUID previously generated by it on a specified computer since Windows was started. The problem with this method however is it is created on the DB side and won’t be useful if you need to pass in a GUID from the client side.

There are a number of options which can be used to generate sequential GUIDs in C# which are compatible with SQL Servers GUID/UUID sorting mechanism, I’ll cover three of them in this post.

Options for generating SQL Server compatible sequential GUIDs

  1. SequentialGuidValueGenerator which is part of Entity Framework core.
    Note at the time of writing the documentation for this is incorrect. It does not generate sequential Guids using the same algorithim as NEWSEQUENTIALID(), however it does indeed generate sequential GUIDs which are sortable with respect to SQL Servers GUID sorting approach. Looking at the source of the method we can see this method calls the regular Guid.NewGuid() and performs byte shuffling to make it optimised for SQL Server. Usage is simple and of course you don’t need to be actually using EF to reference the assembly and just use the function. The generated GUIDs correctly sort in SQL Server.Generating sequential GUIDs in .net
  2. UuidCreateSequential with byte shuffling applied.
    NEWSEQUENTIALID() is a wrapper over the Windows UuidCreateSequential function with some byte shuffling applied. We can therefore call this function by importing the relevant .dll and rearrange the bytes in the same way as SQL Server does to get sequential GUIDs in C#. The link above from StackOverflow has all the implementation details. Looking at 20 GUIDs created with this approach we can see they are much more uniform than the Sequential GUID algorithm from EF covered above.
    Depending on your scenario a number of problems with this approach may limit its feasiblity:
    1 – Requires DLLImport which may not be allowed/desired and might have permissions issues.
    2- Not cross platform, this is a windows dll, so if your deploying your .net core app to Linux this isn’t a runner.
    3 – If your windows server restarts your GUIDs may start from a lower range thus causing index fragmentation.
    4 – Can’t be used in cluster environment where mutiple machines write to same DB as GUIDs generated will all be out of synch with each other thus causing index fragmentation.
  3.  COMB GUID.
    The COMB GUID approach was first described by and involves replacing the portion of a normal GUID that is sorted first with a date/time value. This guarantees (within the precision of the system clock) that values will be sequential, even when the code runs on different machines. There are lots of examples of COMB GUIDs in C# online but I like RT.Comb which is a library available on Nuget. Below you can see how its used in its basic configuration.And we can see the GUIDs it creates are sorted correctly in SQL Server…

but wait… actually they are not sorted correctly.  This is because the timestamp is generated using DateTime.UtcNow which has precision of 1/300th of a second meaning that if you quickly generate a lot of COMB Guids like above there is a chance you’ll create two with the same timestamp value. This won’t result in collisions as the non timestamp bits will take care of that but it means COMBs with the same timestamp are not guaranteed to be sorted correctly for insertion into the DB.

Therefore if you’re inserting records faster than the precision offered by DateTime.UtcNow (very possible) these inserts will cause index fragmentation. Avoiding index fragmentation is the whole purpose of using sequential GUIDs in the first place so we need a solution to this if COMBs are to be viable compared to other approaches.

Thankfully a solution is provided by RT.Comb itself and is part of the reason I like to use this library rather than just some of the code for creating COMBs available on StackOverflow or other places online. RT.Comb has a timestamp provider called UtcNoRepeatTimestampProvider which ensures that the current timestamp is at least Xms (4ms is the default, but this can be changed) greater than the previous one and increments the current one by Xms if it is not. The library documentation gives the following table of what timestamp UtcNoRepeatTimestampProvider (RHS) will provide compared to the original DateTime.UtcNow (LHS) timestamp.

02:08:50.613    02:08:50.613
02:08:50.613    02:08:50.617
02:08:50.613    02:08:50.621
02:08:50.617    02:08:50.625
02:08:50.617    02:08:50.629
02:08:50.617    02:08:50.632

Using UtcNoRepeatTimestampProvider is simple and results in GUIDs which are correctly sorted in SQL Server as shown below.

Creating sequential GUIDs in .net

Which Sequential GUID approach to use?

Of course there are many other solutions on the web which you can choose. All three discussed above are super fast. On my machine I did 100K iterations in at most 101 ms so this wouldn’t influence me either way. Given the potential problems outlined with the dll import approach above I’d avoid this unless there were not viable alternatives, which there are.

There’s not much to choose between the other two. If your using EF Core to update your DB then you’ll have SequentialGuidValueGenerator available anyhow so I’d just go with what you have out of the box rather than integrating RT.Comb for example. COMBs are ideal if you want to be able to extract the timestamp out of the GUID for things like debugging, but it does perhaps have limited real world benefit. There are many COMB libraries available online but if you happen to use both SQL Server and PostgreSQL RT.Comb is ideal as it supports both.

Note Sequential GUIDs by their nature are guessable so don’t use these in a security sensitive context.

 

Viewing SQL generated by Entity Framework when querying or calling SaveChanges()

When using Entity Framework, in an effort to track down bugs or performance problems, it’s very handy to see what SQL Entity Framework is generating and sending to the DB when you run a lambda/linq query or indeed make a call to SaveChanges().

This is easy once you know how. Simple add this.Database.Log = x => System.Diagnostics.Debug.WriteLine(x); to the constructor of your database context class (the one that derives from DbContext):

dbcontext

Afterwards you should see all the queries Entity Framework is sending to the DB in your output window.

Validation failed for one or more entities. See ‘EntityValidationErrors’ property for more details

You may see this exception when doing a DbContext.SaveChanges() call. You then may go drilling into the exception details to find what the specific problem was and notice there’s nothing of value there.  A simple way of getting access to the EntityValidationErrors collection and actually seeing what’s in it is to add a watch for it:

((System.Data.Entity.Validation.DbEntityValidationException)$exception).EntityValidationErrors

Just copy and paste the above watch expression into the watch window and afterwards you can drill down to see what the problem(s) is. Thanks to Yoel Halb for this answer.