Logging all SQL statements done by Entity Framework

One of the disadvantages of using an ORM is that your application doesn’t know which SQL commands are being executed. In this post I’m going to show you how to log all the SQL statements that are executed by Entity Framework. This is very useful if you want to look at the query executed and the time take by each to catch some possible pitfalls, or to keep a log of all the commands executed if you have your own custom replication/synchronization strategy.

The need

I was exactly in that latter scenario: the backend acts on one DB, while the frontend reads data from another DB. And for many reasons we are not using standard SQL Server replication. Instead we have a custom replication in place: we log all the SQL UPDATE, INSERT, DELETE to a journal table and we have a scheduled script that gets all the statements from the source DB and executes them in the destination DB. Using standard data access technologies this is simple: when we create the SQL statement we also store it in the journal table: but with ORM we are not in control of that process anymore.

The solution

Unfortunately Entity Framework misses the Log property that Linq2Sql had so I needed to go a bit more inside the core. I knew that EF had some kind of interceptor because otherwise the EFProfiler would have not been possible, so a bit of googling brought me to the Tracing and Caching Provider Wrappers for Entity Framework, developed by Jaroslaw Kowalski. These providers, together with a small sample file you have to copy your application, gives you the possibility to get the Log property back, to inject a Cache or to do more advanced operations using the CommandExecuting, CommandFinished, CommandFailed events. You can read more about the API in the blog post where they announce it.

For my specific scenario I had to write an handler for the CommandFinished event that gets the DbCommand object and transforms it to the SQL statement.

How to do it

Let’s see how this is done.

1 - Get the providers

First thing you have to download the provider wrappers with the sample apps from the MSDN Gallery site. The latest version (v1.02) is for EF v4, but if you are like me and are still using EF v1 you have to get version 1.

The file you get is just a Visual Studio Solution, so you have to open it, change the configuration to Release and build it. You then open the EFProviderWrapperDemo project, go the Bin\Release folder and get the 3 DLLs: FCachingProvider.dll, EFTracingProvider.dll and EFProviderWrapperToolkit.dll.

2 – Setting up your application

You take the 3 DLLs mentioned above and you add them as references to you application: the EFProviderWrapperToolkit is always needed, and then the one that you need for your application: in my scenario I didn’t need caching, so I just added the EFTracingProvider one.

Then the tricky part comes: from the EFProviderWrapperDemo project you have to take the ExtendedNorthwindEntities.cs file, copy in the folder where you have your Entity Framework edmx file, and modify it to match your scenario (change the name of the class and the connection string). For example, my EDMX file was called PhotoLibEntities, so I renamed the file (and class) to ExtendedPhotoLibEntities, and modified the code as follows:

public partial class ExtendedPhotoLibEntities : PhotoLibEntities
{
    private TextWriter logOutput;

    public ExtendedPhotoLibEntities()
        : this("name=PhotoLibEntities")
    {
    }

    public ExtendedPhotoLibEntities(string connectionString)
        : base(EntityConnectionWrapperUtils.CreateEntityConnectionWithWrappers(
                connectionString,
                "EFTracingProvider"
        ))
    {
    }
...
}

Notice that if you need just one provider, you can remove the registration of the one you don’t need (as I did).

You also need to register the provider in you application putting some entries in the app.config (or web.config) file:

<system.data>
  <DbProviderFactories>
    <add name="EF Tracing Data Provider"
         invariant="EFTracingProvider"
         description="Tracing Provider Wrapper"
         type="EFTracingProvider.EFTracingProviderFactory, EFTracingProvider, Version=1.0.0.0, Culture=neutral, PublicKeyToken=def642f226e0e59b" />
    <add name="EF Generic Provider Wrapper"
         invariant="EFProviderWrapper"
         description="Generic Provider Wrapper"
         type="EFProviderWrapperToolkit.EFProviderWrapperFactory, EFProviderWrapperToolkit, Version=1.0.0.0, Culture=neutral, PublicKeyToken=def642f226e0e59b" />
  </DbProviderFactories>
</system.data>

Here I added only the tracing provider, but if you needed the caching provider, you have to add it in the configuration file as well.

If you don’t want, or cannot change your code, you can also inject the provider by manually modifying the SSDL files. You can read more about this in the original blog post by Jaroslaw Kowalski.

3 – Using the Extended ObjectContext

Now that everything is correctly setup you can use the extended ObjectContext to have access to the logging and caching features provided by the wrapper.

using (ExtendedPhotoLibModel context = CreateExtendedPhotoLibModel())
{
    //Do stuff
    context.SaveChanges();
}

I use an helper method instead of instantiating the extended context directly because this way I can setup the event handler I need to store the statements to the journal table.

private ExtendedPhotoLibModel CreateExtendedPhotoLibModel()
{
    ExtendedPhotoLibModel context = new ExtendedPhotoLibModel();

    photoLibModel.CommandFinished += (sender, e) =>
    {
        if (e.Method.Equals("ExecuteNonQuery"))
        {
            string sqlStr = e.Command.CommandText;
            foreach (DbParameter parameter in e.Command.Parameters)
            {
                sqlStr = sqlStr.Replace(parameter.ParameterName,
                            ToDbFormattedString(parameter.Value));
            }
            sqlStr = sqlStr.Replace("\r\n", " ");
            PhotoJournalLogger.AddEntry(sqlStr);
        }
    };
    return context;
}

private static string ToDbFormattedString(object p)
{
    if (p is DateTime)
        return "CONVERT(datetime,'" + ((DateTime) p).ToShortDateStr() + "',103)";
    if (p is String)
        return "'" + (p as string).Replace("'", "''") + "'";
    return p.ToString();
}

My event handler gets the command text, cycles through the parameters and modifies the command text replacing the parameter’s names with their values.

Here is an example of how the CommandText looks like:

update [dbo].[NEWS_PHOTOGALLERY]
set [bookID] = @0,
    [date] = @1,
    [numPhoto] = @2,
    [picture] = null,
    [status] = @3,
    [titleID] = null
where ([id] = @4)

If you just need to log the statements you could also call the e.ToTraceString() method and you would have got the following text (with also all the values for the parameters):

update [dbo].[NEWS_PHOTOGALLERY]
    [date] = @1,
    [numPhoto] = @2,
    [picture] = null,
    [status] = @3,
    [titleID] = null
where ([id] = @4)

-- @0 (dbtype=Int32, size=0, direction=Input) = 34
-- @1 (dbtype=DateTime, size=0, direction=Input) = 08/12/2010 12.21.38
-- @2 (dbtype=Int32, size=0, direction=Input) = 0
-- @3 (dbtype=AnsiStringFixedLength, size=1, direction=Input) = "0"
-- @4 (dbtype=Int32, size=0, direction=Input) = 234

Further usages

This is just the basic usage, but if you want you can extend the logging to also include the duration of the command (very useful for performance tuning) or even the whole command tree.

I struggled a bit to find the solution, and I hope this helps.

Tags: Entity Framework,tracing,caching