Entity Framework and LINQ to Entities (3) Logging

[LINQ via C#] - [Entity Framework]

As fore mentioned, this tutorial will use SQL Profiler to trace the remote SQL queries, which are translated from the LINQ to Entities queries. This is most close the the truth, because the tracing uncovers the actual SQL query executed in SQL database. Entity Framework also provides several options to log the translated SQL database operations programmatically.

DbQuery<T>.ToString

For queries, the easiest way is to call ToString method on the IQueryable<T> object. In LINQ to Entities query, the IQueryable<T> is actually implemented with System.Data.Entity.Infrastructure.DbQuery<T>. DbQuery<T>.ToString returns its SQL translation:

internal static partial class Log
{
    internal static void DbQueryToString()
    {
        using (AdventureWorks adventureWorks = new AdventureWorks())
        {
            IQueryable<ProductCategory> source = adventureWorks.ProductCategories; // Define query.
            string translatedSql = source.ToString();
            Trace.WriteLine(translatedSql);
            // SELECT 
            //    [Extent1].[ProductCategoryID] AS [ProductCategoryID], 
            //    [Extent1].[Name] AS [Name]
            //    FROM [Production].[ProductCategory] AS [Extent1]
            source.ForEach(category => Trace.WriteLine(category.Name)); // Execute query.
        }
    }
}

Database.Log

Besides LINQ to Entities queries, Entity Framework also supports other database operations, like updating the database. So a more general logging API is provides. The DbContext class has a Database property to expose a System.Data.Entity.Database object, where a Log action can be specified:

namespace System.Data.Entity
{
    public class DbContext : IDisposable, IObjectContextAdapter
    {
        public Database Database { get; }
    </span><span style="color: green;">// Other members.
</span><span style="color: black;">}

</span><span style="color: blue;">public class </span><span style="color: #2b91af;">Database
</span><span style="color: black;">{
    </span><span style="color: blue;">public </span><span style="color: #2b91af;">Action</span><span style="color: black;">&lt;</span><span style="color: blue;">string</span><span style="color: black;">&gt; Log { </span><span style="color: blue;">get</span><span style="color: black;">; </span><span style="color: blue;">set</span><span style="color: black;">; }

    </span><span style="color: green;">// Other members.
</span><span style="color: black;">}

}

The Log action will be called for all database operations:

internal static void DatabaseLog()
{
    using (AdventureWorks adventureWorks = new AdventureWorks())
    {
        adventureWorks.Database.Log = log => Trace.Write(log);
        IQueryable<ProductCategory> source = adventureWorks.ProductCategories; // Define query.
        source.ForEach(category => Trace.WriteLine(category.Name)); // Execute query.
        // Opened connection at 5/21/2016 12:33:34 AM -07:00
        // SELECT 
        //    [Extent1].[ProductCategoryID] AS [ProductCategoryID], 
        //    [Extent1].[Name] AS [Name]
        //    FROM [Production].[ProductCategory] AS [Extent1]
        // -- Executing at 5/21/2016 12:31:58 AM -07:00
        // -- Completed in 11 ms with result: SqlDataReader4
        // Closed connection at 5/21/2016 12:33:35 AM -07:00
    }
}

IDbCommandInterceptor

For low-level logging control, Entity Framework provides System.Data.Entity.Infrastructure.Interception.IDbCommandInterceptor interface:

namespace System.Data.Entity.Infrastructure.Interception
{
    public interface IDbCommandInterceptor : IDbInterceptor // IDbInterceptor is an empty interface.
    {
        void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);
    </span><span style="color: blue;">void </span><span style="color: black;">NonQueryExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">int</span><span style="color: black;">&gt; interceptionContext);

    </span><span style="color: blue;">void </span><span style="color: black;">ReaderExecuted(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: #2b91af;">DbDataReader</span><span style="color: black;">&gt; interceptionContext);

    </span><span style="color: blue;">void </span><span style="color: black;">ReaderExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: #2b91af;">DbDataReader</span><span style="color: black;">&gt; interceptionContext);

    </span><span style="color: blue;">void </span><span style="color: black;">ScalarExecuted(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">object</span><span style="color: black;">&gt; interceptionContext);

    </span><span style="color: blue;">void </span><span style="color: black;">ScalarExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">object</span><span style="color: black;">&gt; interceptionContext);
}

}

Here is a simple implementation:

internal class DbCommandInterceptor : IDbCommandInterceptor
{
    private readonly Action<string> log;
</span><span style="color: blue;">internal </span><span style="color: black;">DbCommandInterceptor(</span><span style="color: #2b91af;">Action</span><span style="color: black;">&lt;</span><span style="color: blue;">string</span><span style="color: black;">&gt; log)
{
    </span><span style="color: blue;">this</span><span style="color: black;">.log = log;
}

</span><span style="color: blue;">public void </span><span style="color: black;">NonQueryExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">int</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.NonQueryExecuting), interceptionContext, command);

</span><span style="color: blue;">public void </span><span style="color: black;">NonQueryExecuted(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">int</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.NonQueryExecuting), interceptionContext);

</span><span style="color: blue;">public void </span><span style="color: black;">ReaderExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: #2b91af;">DbDataReader</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.ReaderExecuting), interceptionContext, command);

</span><span style="color: blue;">public void </span><span style="color: black;">ReaderExecuted(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: #2b91af;">DbDataReader</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.ReaderExecuted), interceptionContext);

</span><span style="color: blue;">public void </span><span style="color: black;">ScalarExecuting(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">object</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.ScalarExecuting), interceptionContext, command);

</span><span style="color: blue;">public void </span><span style="color: black;">ScalarExecuted(</span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: blue;">object</span><span style="color: black;">&gt; interceptionContext) =&gt;
    </span><span style="color: blue;">this</span><span style="color: black;">.Log(</span><span style="color: blue;">nameof</span><span style="color: black;">(</span><span style="color: blue;">this</span><span style="color: black;">.ScalarExecuted), interceptionContext);

</span><span style="color: blue;">private void </span><span style="color: black;">Log&lt;</span><span style="color: #2b91af;">TResult</span><span style="color: black;">&gt;(
    </span><span style="color: blue;">string </span><span style="color: black;">@event, </span><span style="color: #2b91af;">DbCommandInterceptionContext</span><span style="color: black;">&lt;</span><span style="color: #2b91af;">TResult</span><span style="color: black;">&gt; interceptionContext, </span><span style="color: #2b91af;">DbCommand </span><span style="color: black;">command = </span><span style="color: blue;">null</span><span style="color: black;">)
{
    </span><span style="color: #2b91af;">Exception </span><span style="color: black;">exception = interceptionContext.Exception;
    </span><span style="color: blue;">if </span><span style="color: black;">(command == </span><span style="color: blue;">null</span><span style="color: black;">)
    {
        </span><span style="color: blue;">this</span><span style="color: black;">.log(exception == </span><span style="color: blue;">null </span><span style="color: black;">? @event : </span><span style="color: #a31515;">$"</span><span style="color: black;">{@event}</span><span style="color: #a31515;">: </span><span style="color: black;">{exception}</span><span style="color: #a31515;">"</span><span style="color: black;">);
    }
    </span><span style="color: blue;">else
    </span><span style="color: black;">{
        </span><span style="color: blue;">this</span><span style="color: black;">.log(</span><span style="color: maroon;">$@"</span><span style="color: black;">{@event}</span><span style="color: maroon;">: </span><span style="color: black;">{command.CommandText}{</span><span style="color: blue;">string</span><span style="color: black;">.Concat(command.Parameters
            .Cast&lt;</span><span style="color: #2b91af;">DbParameter</span><span style="color: black;">&gt;()
            .Select(parameter =&gt; </span><span style="color: #a31515;">$", </span><span style="color: black;">{parameter.ParameterName}</span><span style="color: #a31515;">=</span><span style="color: black;">{parameter.Value}</span><span style="color: #a31515;">"</span><span style="color: black;">))}</span><span style="color: maroon;">"</span><span style="color: black;">);
        </span><span style="color: blue;">if </span><span style="color: black;">(exception != </span><span style="color: blue;">null</span><span style="color: black;">)
        {
            </span><span style="color: blue;">this</span><span style="color: black;">.log(</span><span style="color: maroon;">$@"</span><span style="color: black;">{@event}</span><span style="color: maroon;">: </span><span style="color: black;">{exception}</span><span style="color: maroon;">"</span><span style="color: black;">);
        }
    }
}

}

An interceptor has to be registered with System.Data.Entity.Infrastructure.Interception.DbInterception.Add:

internal static void DbCommandInterceptor()
{
    DbCommandInterceptor dbCommandTrace = new DbCommandInterceptor(message => Trace.WriteLine(message));
    DbInterception.Add(dbCommandTrace);
    using (AdventureWorks adventureWorks = new AdventureWorks())
    {
        IQueryable<ProductCategory> source = adventureWorks.ProductCategories; // Define query.
        source.ForEach(category => Trace.WriteLine(category.Name)); // Execute query.
        // ReaderExecuting: SELECT 
        //    [Extent1].[ProductCategoryID] AS [ProductCategoryID], 
        //    [Extent1].[Name] AS [Name]
        //    FROM [Production].[ProductCategory] AS [Extent1]
        // ReaderExecuted
    }
    DbInterception.Remove(dbCommandTrace);
}

16 Comments

Add a Comment

As it will appear on the website

Not displayed

Your website