Logging Database Operations in Entity Framework 6 - EF6 New Feature

In this blog post you will learn a new feature ‘Logging Database Operations’ introduced with Entity Framework 6. This features works for models created with Code First or the EF Designer.

This new feature gives us opportunity to log every command and query that we send to database. This is the easiest way to see what’s happening with 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 running and whole bunch of stuff. So, now we have this feature integrated with EF6. The primary use of this feature is to debug unexpected behaviour/result and troubleshoot performance issue by looking at execution report like time took to execute query etc. This also helps us to see how EF translates LINQ query into SQL query.

In my previous post of this series ‘Custom Code First Conventions’, I already set-up a console application, here 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 different location.

Logging at Command Line

Look at the following code, its simple and self-explanatory, the only thing new here is write DbContext.Database.Log command at the beginning. 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 above code, it displayed me all bunch of queries on the command line. If you take a closer look at above code, you will find three different queries expected to execute and the same thing happen, you can see it in the log. You will see extra log information also that includes all the work migrations does under the covers to check for or create a new database. Here is output.

In the above output you will see following things got logged for you.

1. SQL Commands including relationships generated by Lazy Loading, you can’t see it in above output ;)

2. Parameters

3. Timestamp with information like asynchronous query or not.

4. Completed, Failed, Cancelled command information with time it took etc

Now, let’s look at a way to log these information to different location.

Logging to different location

It is also easy to log to memory, file, database etc. by using different 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 console.

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

Hope it helps.