Logging and tracing with Entity Framework 6

Logging is important, especially when you have to troubleshoot an issue. That's when you realize that without logging you are "driving blind". Today's post is about logging with Entity Framework 6. I agree that there are tools out there that can help you with EF troubleshooting, such as Glimpse (if you are on a web application), SQL Server profiling etc. However, EF6 makes it extremely easy to log and trace executed statements and in this post I will show you how you can leverage this feature to create a robust and efficient logging solution for your application.

Simple logging

If all you need to do is capture the executed statement, then this solution is more than adequate. Instead of using SQL Server profiler to capture the statements, a useful tool nonetheless, you can just use the following code to output directly to the Console:

Alternatively, if you want to divert the log output to the trace window then you can just write this:

Finally, if you already have a logging framework in place and you want to use that for EF logging, then EF's got you covered as well. You can just use the following command to output to your logger:

Notice that in this example I'm using the Common.Logging framework to abstract the whole logging process and decouple it from any specific logging implementation. I wrote about Common.Logging here

What's in the output

If you're wondering what gets logged, then rest assured that you get a wealth of information about the code execution:

• Queries, including normal LINQ queries, eSQL queries, and raw queries from methods such as SqlQuery
• Inserts, updates, and deletes generated as part of SaveChanges
• Relationship loading queries such as those generated by lazy loading
• The parameters passed to the quiery
• Whether or not the command is being executed asynchronously
• A timestamp indicating when the command started executing
• Command outcome
  • Success
  • Failure by throwing an exception
  • Cancellation, for async
• The result value when possible
• The time it took to execute the command

Logging with interception

I believe that interception is where logging with EF can truly shine. Using this approach you can capture a lot more information transiently without having to litter your code with Log.Debug("somemessage"); statements. To implement this, you need to create your own custom interceptor and register it accordingly:

Again, note that I rely on Common.Logging to provide the logging abstraction. With the interceptor in place, all we need to do is register it and let it do its job. There are a few ways and places to register the interceptor:

Technically, you can add your interceptor(s) anywhere in your code, however it's good practice to keep it centralized. The reason being that if you register the same interceptor more than once, you'll get additional interceptor instances and you'll get duplicate logs. Another thing to note is that if you use multiple interceptors, say an error specific one and an normal execution one, then they will be executed in the order of registration.

I hope you found this useful.