Logging Database Operations in Entity Framework

In this article, you will learn the new feature "Logging Database Operations" introduced with Entity Framework 6. This feature works for models created with Code First or the EF Designer.

This new feature gives us the opportunity to log every command and query sent to the database. This is the easiest way to see what's happening with the database under the hood. In the past, we fire up SQL Profiler by installing SQL Server Management Studio and configure it just to see what EF request is running and a whole bunch of stuff. So, now we have this feature integrated with EF6. The primary use of this feature is to debug unexpected behavior/results and troubleshoot performance issues by looking at an execution report such as the time required to execute a query and so on. This also helps us to see how EF translates a LINQ query into a SQL query.

In my previous article of this series, "Custom Code First Conventions", I already set up a console application, and I'm going to use that application to explore this logging feature. However, you can try it with any application you want. So, let's directly jump and talk about Logging Database Operations.

We can log database operations on the command line or at a different location.

Logging at the Command line

Look at the following code, it's simple and self-explanatory, the only thing new here is the write DbContext.Database.Log command at the beginning. The DbContext.Database.Log property can be set to a delegate for any method that takes a string. In particular, it can be used with any TextWriter by setting it to the "Write" method of that TextWriter. All SQL generated by the current context will be logged to that writer. In the example given below, DbContext.Database.Log is set to Console. Write.

class Program  
{  
    static void Main(string[] args)  
    {  
        using (var context = new StateContext())  
        {  
            context.Database.Log = Console.Write;  
   
            InsertRecords(context);  
            SelectRecords(context);  
            Console.ReadKey();  
        }  
    }  
    private static void SelectRecords(StateContext context)  
    {  
        var stdQuery = (from d in context.States  
                        select new { StateName = d.StateName });  
        foreach (var q in stdQuery)  
        {  
            Console.WriteLine("Name : " + q.StateName);  
        }  
    }  
    private static void InsertRecords(StateContext context)  
    {  
        context.States.Add(new State { StateName = "State " + (context.States.Count() + 1)});  
        context.SaveChanges();  
    }  
}  

Once I executed the code above, it displayed an abundance of queries to the command line. If you take a closer look at the code above, you will find three different queries expected to execute and the same thing happens, you can see it in the log. You will see extra log information also that includes all the work that the migrations do under the covers to check for or create a new database. Here is the output.

In the preceding output, you will see that the following things got logged for you.

1. SQL Commands, including relationships generated by Lazy Loading, you can't see it in the output above ;).
2. Parameters.
3. Timestamp with information like asynchronous query or not.
4. Completed, Failed, and Cancelled command information with the time it took, and so on.

Now, let's look at a way to log this information to a different location.

Logging to a different location

It is also easy to log to memory, a file, a database, and so on using various kinds of TextWriter. In the example given below, I have a class "MyLogger" with a method "Log" that accepts a string and writes it to the console.

We can do more things, such as change the log format and customize it by writing a class that inherits "DatabaseLogFormatter".

Hope it helps.

Thanks.