EF6 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:

  • A Log property for the context similar to DataContext.Log in LINQ to SQL
  • A mechanism to customize the content and formatting of the output sent to the log
  • Low-level building blocks for interception giving greater control/flexibility

(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!"});

    context.SaveChangesAsync().Wait();
}

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

SELECT TOP (1)
[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

SELECT
[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

(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:

  • SQL for all different kinds of commands. For example:
    • 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
  • Parameters
  • Whether or not the command is being executed asynchronously
  • A timestamp indicating when the command started executing
  • Whether or not the command completed successfully, failed by throwing an exception, or, for async, was canceled
  • Some indication of the result value
  • The approximate amount of time it took to execute the command

Looking at the example output above, each of the four commands logged are:

  • The query resulting from the call to context.Blogs.First
    • Notice that the ToString method of getting the SQL would not have worked for this query since “First” does not provide an IQueryable on which ToString could be called
  • The query resulting from the lazy-loading of blog.Posts
    • Notice the parameter details for the key value for which lazy loading is happening
    • Only properties of the parameter that are set to non-default values are logged. For example, the Size property is only shown if it is non-zero.
  • Two commands resulting from SaveChangesAsync; one for the update to change a post title, the other for an insert to add a new post
    • Notice the parameter details for the FK and Title properties
    • Notice that these commands are being executed asynchronously

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:

  • If  all you need to do is control the format and content of the strings that are logged then this can be done while still hooking the Log property to a TextWriter in a simple way. See part 2 of this series for details.
  • In part 3 of this series we’ll look at a lower-level way to log directly to something that isn’t a TextWriter without using Log at all.

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.

About Arthur Vickers

Developer on the Entity Framework team at Microsoft.
This entry was posted in DbContext API, Entity Framework and tagged , , . Bookmark the permalink.

20 Responses to EF6 SQL Logging – Part 1: Simple Logging

  1. simmdan says:

    Sweet!

    Getting EF logging properly integrated into my app has been on my to-do list for a while. It always gets pushed aside, upped in priority when I have to debug something, and then pushed aside again when the issue gets resolved before the logging work is complete. :-(

    Having simple-to-turn on logging built in will be a big help.

    – Danny

    P.S. Say hi to everyone on the team. I’m having a lot of fun at my latest gig (which uses EF as a fundamental part of our core app), but I still miss working with you folks.

  2. UnaiZorrilla says:

    Super,
    Good to hear that Danny also here!!!

    Unai

  3. uzorrilla says:

    Super!!!

    Unai

  4. André says:

    You should add ETW support and trace it there by default if someone listens to the provider.

  5. Telly Brown says:

    Did this make the Beta1? I don’t see Database.Log

  6. SadProgrammer says:

    Dear Arthur
    I think it is time to start listening to the community and the way they want it
    low level log is amazing for developers but not for business
    business requires something simple and readable
    Logs can be a deciding factor between available ORM
    and I really hope that EF team will support the community and act accordingly
    the majorty spend countless time in managing logs
    can you push EF team to this design which consist of two tables:
    (AuditEntry)
    AuditID
    TABLENAME
    OPERATION [Insert,Update,Delete]
    PrimaryKey [If available]

    (AuditProperties)
    P_AuditID
    PropertyName
    OldValue
    NewValue

    are we asking for a big innovation here
    please check this amazing implementation
    DoddleAudit on codeplex which support Linq2Sql and partialy EF
    because most implementations cannot log primary keys in insert operations (without extra effort) which is the same situation in low level log described above.
    only doddleaudit managed it so far
    Auditing is an ABC in mature ORM but I cannot understand why EF wants to stay at entry-level ORM

    • @SadProgrammer You are free to implement any format that you choose for the log, as described in parts two and three of this series. If the information that you want to log is not included in the command that is being logged then its going to be more complicated because you would need to somehow find that information. So far the community has provided positive feedback on this feature and the format and extensibility seem to be working for the people that have contacted us. If there is something specific that you are finding hard to do then please let us know and we will consider the feedback as well as helping if we can. However, I doubt we will change the default behavior since the feedback has been positive about it.

      Thanks,
      Arthur

      • Marco Monducci says:

        hi Arthur, first of all thank you very much for your great ability to transfer knowledge with passion.
        Moving back to the topic, I have spent my last 6 years designing large scale enterprise (>>TB) software architectures and build up the core parts of these systems using ORM, some year ago I gave EF a chance and I definitively got in love with it.
        Anyway, at the moment I agree with SagProgrammer, each time I build up my Model I had to write my own fine audit system exactly as he described above.

        An out-of-the-box audit system endpoint will be very appreciate, it doesn’t matter the way you would like to implement it, it will be enough to have something already done.

        Hope this could help
        mM

      • @Marco Monducci Somebody (possibly you?) recently posted a similar question on the CodePlex site. We have triaged it as something consider for the future. See Rowan’s reply for more details: https://entityframework.codeplex.com/workitem/1671

        Thanks,
        Arthur

  7. SadProgrammer says:

    Hi again
    Happy to see others start speaking their minds because it is a matter of partnership between users and vendors.
    this time I’m posting after the release of EF6 and I really appreciate the amount of effort to build it.
    I just want to imply a note from watching major vendors and how they push their new innovations.
    most vendors went after extensibility in their early stages of their products. Afterward, they started
    squeezing their product to simplify them for customers and cut dow the maintenance cost.
    Microsoft products are great and incomparable in the market. however, they lean towards uncontrolled continues expanding and stretching. This makes them the most flixible products for any customer.but with a downside of [[[[ LEARNING CURVE + FAST DEPRECIATION ]]]].
    One exception in the latest release which I admired a lot is ASP One initiative. Although it is not final yet. but definitly it is a step in the right direction.
    The same case for entity framework when it unified all data access methodologies in .Net framework.
    Believe me when I tell that this product can become a standard in ORM.
    On a condition of focusing on productivity instead of extensibility in future releases.
    Until now you can not market EF as a time saver like other major ORMs.

    I know that you can forward our message to the right person and convince him/her about the community demands.

    Regards,
    SadProgrammer

  8. Annejan Barelds says:

    Hi Arthur,

    It’s good fun to poke around in the interception features. I do have a question though: am I correct in understanding that the lifetime of an interceptor instance is not equal to the lifetime of a single query, which would limit its usage to single-threaded scenarios? Put differently: if I use EF in a web application and two requests are executing simultaneously (with both having their own DBContext instance), will they both make use of the same DatabaseLogFormatter instance, meaning that the member variable of type Stopwatch that is used internally to time the requests is no longer reliable?

    If so, it would be nice to be able to pass some sort of state from the …Executing to the …Executed-methods in order to associate the two on a per-query basis. It seems that, as things stand, I have to implement my own IDbCommandInterceptor that keeps track of this state based on the passed in DBContexts. In my scenario this could probably be done, but it doesn’t feel quite right.

    Also, if my understanding of the way this works is correct, it may make sense to explicitly mention this in the different blogs. Especially the one on turning on logging without recompiling suggested (at least to me) that this is a viable approach to diagnosing an existing application. And while that can indeed be done, using the default DatabaseLogger will probably not work as expected in any non-trivial implementation.

    • @Annejan The change to pass state from the executing to executed methods was contributed recently and should be released in EF 6.1.2. Beyond that, normally logging is associated with a single context instance, which means that there should not be any issues because context instances cannot be used concurrently. We discussed this at the time and decided it was okay. We later added the way to add the interceptor in config which makes it easy to setup logging for all contexts at the same time. In this situation the timing is not going to be accurate. We would likely accept a contribution to use the existing/executed state for the timer object. I may do it myself, but I’m pretty busy with other stuff so don’t hold your breath.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s