EF6 SQL Logging – Part 2: Changing the content/formatting

In part 1 we saw how DbContext.Database.Log can be used to easily log SQL to the console or some other TextWriter. This post covers how the context and formatting of the output can be changed.

DatabaseLogFormatter

Under the covers the Database.Log property makes use of a DatabaseLogFormatter object. This object effectively binds a IDbCommandInterceptor implementation (see part 3 of this series) to a delegate that accepts strings and a DbContext. This means that interception methods on DatabaseLogFormatter are called before and after the execution of commands by EF. These DatabaseLogFormatter methods gather and format log output and send it to the delegate.

Changing what is logged and how it is formatted can be achieved by creating a new class that derives from DatabaseLogFormatter and then overriding methods as appropriate. The most common methods to override are:

  • LogCommand – Override this to change how commands are logged before they are executed. By default LogCommand calls LogParameter for each parameter; you may choose to do the same in your override or handle parameters differently instead.
  • LogResult – Override this to change how the outcome from executing a command is logged.
  • LogParameter – Override this to change the formatting and content of parameter logging.

For example, suppose we wanted to log just a single line before each command is sent to the database. This can be done with two overrides:

  • Override LogCommand to format and write the single line of SQL
  • Override LogResult to do nothing. (Executed could be overridden instead and this would probably be slightly more efficient, but functionally equivalent.)

The code would look something like this:

public class OneLineFormatter : DatabaseLogFormatter
{
    public OneLineFormatter(DbContext context, Action<string> writeAction)
        : base(context, writeAction)
    {
    }

    public override void LogCommand<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        Write(string.Format(
            "Context '{0}' is executing command '{1}'{2}",
            Context.GetType().Name,
            command.CommandText.Replace(Environment.NewLine, ""),
            Environment.NewLine));
    }

    public override void LogResult<TResult>(
        DbCommand command, object result, DbCommandInterceptionContext<TResult> interceptionContext)
    {
    }
}

To log output simply call the Write method which will send output to the configured write delegate.

(Note that this code does simplistic removal of line breaks just as an example. It will likely not work well for viewing complex SQL.)

Setting the DatabaseLogFormatter

Once a new DatabaseLogFormatter class has been created it needs to be registered with EF. This is done using code-based configuration. In a nutshell this means creating a new class that derives from DbConfiguration in the same assembly as your DbContext class and then calling SetDatabaseLogFormatter in the constructor of this new class. For example:

public class MyDbConfiguration : DbConfiguration
{
    public MyDbConfiguration()
    {
        SetDatabaseLogFormatter(
            (context, writeAction) => new OneLineFormatter(context, writeAction));
    }
}

Using the new DatabaseLogFormatter

This new DatabaseLogFormatter will now be used anytime Database.Log is set. So, running the code from part 1 will now result in the following output:

Context 'BlogContext' is executing command '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)'
Context 'BlogContext' is executing command 'SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1'
Context 'BlogContext' is executing command 'update [dbo].[Posts]set [Title] = @0where ([Id] = @1)'
Context 'BlogContext' is executing command 'insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()'

More control?

In the next post we’ll take a look at implementing IDbCommandInterceptor directly for even more control of command interception and show an example that integrates directly with NLog without using the Database.Log property.

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.

5 Responses to EF6 SQL Logging – Part 2: Changing the content/formatting

  1. Kim Tranjan says:

    Awesome! Seriously :D.

  2. Cool! I really like the new Interception API and I am happy that it went into EF6.
    I have implemented an IDbCommandInterceptor for our application and it works really nice.

    One Question: Is there a simple way to get a formatted sql with all bound parameters replaced in the command text so that I can just copy + paste this SQL in SQL-Management-Studio and execute it?

    • @rothdave There has been a lot of discussion over whether to try to generate executable SQL as opposed to outputting the actual SQL that is sent. There are two approaches to executable SQL. The first is simple inlining of parameters. However, there is often value in seeing the parameters that are being used and it also could be confusing if we log different SQL than that which is actually sent. So we decided to not do this by default, but to instead create a different DbCommandLogger class that can be swapped in to do this. However, this probably won’t get done for EF6.

      The other approach is to add comment lines that, when uncommented, would setup the parameters. This way you still get all the parameter information and the actual SQL that is sent to the database. However, this is not doable in a provider-agnostic way without considerable work, and may still not be possible for some providers. It would also produce very verbose output. So we are not doing this for now.

      • A client had an interesting experience with this last week where they were copying the profiled SQL shown by LINQPad directly into SSMS and it’s perf was really slow. But turns out the way LINQPad expressed teh SQL by declaring parameters in advance rather than inline was the cause of the bad perf whereas the actual query executed from the app was quite fast. It sounds like the same type of problem you guys were worried about encountering.

      • Thanks Julie. That’s good info to have.

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