Entity Framework 6.0

SQL Logging - Part 1: Simple Logging

On the EF team we made a late decision to add some support for interception and logging of generated SQL in EF6. To this end recent checkins have added support for:

(Note that most of what is described here came in too late and is therefore not part of the beta 1 release. Instead you can try it out using a recent nightly build and it will be included in the upcoming RC release.)

Context Log property

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. For example, the following code will log SQL to the console:
using (var context = new BlogContext())
    context.Database.Log = Console.Write;

    // Your code here...

Notice that context.Database.Log is set to Console.Write. This is all that is needed to log SQL to the console.

Let's add some simple query/insert/update code so that we can see some output:

using (var context = new BlogContext())
    context.Database.Log = Console.Write;

    var blog = context.Blogs.First(b => b.Title == "One Unicorn");

    blog.Posts.First().Title = "Green Eggs and Ham";

    blog.Posts.Add(new Post { Title = "I do not like them!"});


At the time of writing this will generate the following output, although we may change this format before EF6 is released:

[Extent1].[Id] AS [Id],
[Extent1].[Title] AS [Title]
FROM [dbo].[Blogs] AS [Extent1]
WHERE (N'One Unicorn' = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 5/13/2013 10:19:04 AM
-- Completed in 4 ms with result: SqlDataReader

[Extent1].[Id] AS [Id],
[Extent1].[Title] AS [Title],
[Extent1].[BlogId] AS [BlogId]
FROM [dbo].[Posts] AS [Extent1]
WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: '1' (Type = Int32)
-- Executing at 5/13/2013 10:19:04 AM
-- Completed in 2 ms with result: SqlDataReader

update [dbo].[Posts]
set [Title] = @0
where ([Id] = @1)
-- @0: 'Green Eggs and Ham' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 5/13/2013 10:19:04 AM
-- Completed in 11 ms with result: 1

insert [dbo].[Posts]([Title], [BlogId])
values (@0, @1)
select [Id]
from [dbo].[Posts]
where @@rowcount > 0 and [Id] = scope_identity()
-- @0: 'I do not like them!' (Type = String, Size = -1)
-- @1: '1' (Type = Int32)
-- Executing asynchronously at 5/13/2013 10:19:04 AM
-- Completed in 2 ms with result: SqlDataReader</pre>

(Note that this is the output assuming any database initialization has already happened. If database initialization had not already happened then there would be a lot more output showing all the work Migrations does under the covers to check for or create a new database.)

What gets logged

When the Log property is set all of the following will be logged: Looking at the example output above, each of the four commands logged are:

Logging to different places

As shown above logging to the console is super easy. It's also easy to log to memory, file, etc. by using different kinds of TextWriter. Damien Guard wrote a post on this for the LINQ to SQL Log property which also applies to the new property in EF.

If you are familiar with LINQ to SQL (or have looked at the link above) you might notice that in LINQ to SQL the Log property is set to the actual TextWriter object (e.g. Console.Out) while in EF the Log property is set to a method that accepts a string (e.g. Console.Write or Console.Out.Write). The reason for this is that EF is decouple from TextWriter by accepting any delegate that can act as a sink for strings. For example, imagine that you already have some logging framework and it defines a logging method like so:

public class MyLogger
    public static void Log(string component, string message)
        Console.WriteLine("Component: {0} Message: {1} ", component, message);

This could be hooked up to the EF Log property like this:

context.Database.Log = s => logger.Log("EFApp", s);

It's worth keeping two things in mind here:

Result logging

The default logger logs command text (SQL), parameters, and the “Executing” line with a timestamp before the command is sent to the database. A “completed” line containing elapsed time is logged following execution of the command.

Note that for async commands the “completed” line is not logged until the async task actually completes, fails, or is canceled.

The “completed” line contains different information depending on the type of command and whether or not execution was successful.

Successful execution

For commands that complete successfully the output is “Completed in x ms with result: “ followed by some indication of what the result was. For commands that return a data reader the result indication is the type of DbDataReader returned. For commands that return an integer value such as the update command shown above the result shown is that integer.

Failed execution

For commands that fail by throwing an exception, the output contains the message from the exception. For example, using SqlQuery to query against a table that does exit will result in log output something like this:
SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name 'ThisTableIsMissing'.

Canceled execution

For async commands where the task is canceled the result could be failure with an exception, since this is what the underlying ADO.NET provider often does when an attempt is made to cancel. If this doesn't happen and the task is canceled cleanly then the output will look something like this:
update Blogs set Title = 'No' where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

But I want something different!

It has been apparent from discussions among just a few members of the EF team that different people have different opinions on what the log output should contain and how it should be formatted. The default (which may change before we release so please provide feedback about what you like and don't like) is an attempt to provide commonly useful information in an easy-to-read format. However, it is easy to change this output if you want something different. I will cover how to do this in my next post. In a further post I will also cover the lower-level interception hooks that allow more flexible control over what happens when commands are executed.

This page is up-to-date as of May 8th, 2013. Some things change. Some things stay the same. Use your noggin.