Debugging SQL queries with Entity Framework 6

After taking a look at ways to improve the SQL queries generated by Entity Framework and how to dimension your data and how to retrieve it, I want to document a few more interesting tidbits I gathered from Russ Thomas’ course on Pluralsight.

This time, let’s talk about how to:

  • find out what SQL queries Entity Framework generates
  • log all the database commands
  • execute stored procedures and custom SQL queries from Entity Framework

Debugging and logging

When the performance is not where it should be, it is useful to find out what SQL queries are being executed and see where most time is being spent.

SQL Server profiler

A good way to find out what’s going on behind the scenes is to use SQL Server profiler to trace all calls to the database. That way, you can see what SQL statements are being executed, how often, and how much time they take.

Unfortunately I couldn’t get my hands on a license yet so I will leave this for later.

Using ToString() on IQueryables

With Entity Framework, you can very easily find out what the generated SQL is by calling the ToString() method on the query object itself:

using (var db = new AdventureWorks2012Entities())
{
    IQueryable<string> emails = from person in db.People
                             join email in db.EmailAddresses
                             on person.BusinessEntityID equals email.BusinessEntityID
                             select email.EmailAddress1;

    string generatedQuery = emails.ToString(); // show generated SQL query
    Console.WriteLine(generatedQuery);
}

The code above prints the following SQL statement:

SELECT 
    [Extent1].[EmailAddress] AS [EmailAddress]
    FROM [Person].[EmailAddress] AS [Extent1] 

We can see that Entity Framework optimised the query: since we are interested in all email addresses, the join on the Person table is not necessary and a simple select on EmailAddress is performed.

Logging the database operations with DbContext.Database.Log

Logging all database operations can be achieved by assigning the DbContext.Database.Log property with an action that takes a string as a parameter.

Database.Log examples:

using (var db = new CompanyContext())
using (var streamWriter = File.AppendText("database.log"))
{
    // define how to log the database operations
    db.Database.Log = Console.WriteLine;
    db.Database.Log = s => Trace.WriteLine(s);
    db.Database.Log = (string message) => { /* custom loggging */ };
    db.Database.Log = streamWriter.WriteLine;
    
    // perform database operations
    // var query = from person in db.People ...

    // disable logging
    db.Database.Log = (string message) => { /* do nothing */ };
}

You can log the way you choose and disable it later by assigning an empty Action to the Log property again.

Every interaction with the database is logged, including the time and the value of the parameters.

Creating tables

Opened connection at 25.06.2015 11:37:45 +02:00
Started transaction at 25.06.2015 11:37:45 +02:00

CREATE TABLE [dbo].[Departments] (
    [departmentID] [int] NOT NULL IDENTITY,
    [deptName] [nvarchar](max),
    [deptFloor] [nvarchar](max),
    CONSTRAINT [PK_dbo.Departments] PRIMARY KEY ([departmentID])
)
-- Executing at 25.06.2015 11:37:45 +02:00
-- Completed in 8 ms with result: 0

Inserting data

Opened connection at 25.06.2015 11:37:45 +02:00
Started transaction at 25.06.2015 11:37:45 +02:00

INSERT [dbo].[Departments]([deptName], [deptFloor])
VALUES (@0, NULL)
SELECT [departmentID]
FROM [dbo].[Departments]
WHERE @@ROWCOUNT > 0 AND [departmentID] = scope_identity()

-- @0: 'engineering' (Type = String, Size = -1)
-- Executing at 25.06.2015 11:37:45 +02:00
-- Completed in 1 ms with result: SqlDataReader
Committed transaction at 25.06.2015 11:37:45 +02:00
Closed connection at 25.06.2015 11:37:45 +02:00

Retrieving data

Opened connection at 25.06.2015 11:37:45 +02:00

SELECT 
    1 AS [C1], 
    [Extent1].[deptName] AS [deptName]
    FROM [dbo].[Departments] AS [Extent1]
-- Executing at 25.06.2015 11:37:45 +02:00
-- Completed in 0 ms with result: 0

The information found in this log can prove really useful to find errors and problems with queries. It should probably not be enabled at all times for performances reasons, though.

Intercepting commands with IDbCommandInterceptor

Another very neat option is to implement a class that implements the interface IDbCommandInterceptor and to inject it in the database configuration’s command interceptors.

For every command sent to the database, the registered interceptors are called and at that point you take actions depending on the type of the command being executed.

We will be using this mechanism to log all interactions with the database, but it can also be used for different purposes. For example, intercepting DELETEs and inserting an entry into a history table somewhere.

Before going into the details, let’s look at the interface:
IDbCommandInterceptor

namespace System.Data.Entity.Infrastructure.Interception
{
  public interface IDbCommandInterceptor : IDbInterceptor
  {
    void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);

    void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);

    void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext);

    void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext);

    void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);

    void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);
  }
}

There are three types of commands:

  • Scalar: commands that return a single value such as a number
  • Reader: commands that return a data set
  • NonQuery: commands with no return value, such as CREATEs and INSERTs

For each type of command, the distinction between -Executing (command start) and -Executed (command end) is made. That way, we can for example measure the execution time or recognise which commands are aborted and never finished.

We can also notice that commands of type Scalar have a result of type object, Reader a result of type DbDataReader, and NonQuery a result of type int.

For this example, I will simply log all commands in a log file.

Implementation of IDbCommandInterceptor:

public class CustomSqlLogger : IDbCommandInterceptor
{
    public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogSql(command, interceptionContext);
    }

    private void LogSql<T>(DbCommand dbCommand, DbCommandInterceptionContext<T> interceptionContext, [CallerMemberName] string callerMethodName = "")
    {
        using (var fileWriter = File.AppendText(@"sql_commands.log"))
        {
            fileWriter.WriteLine(
                "Intercepted {0}:\n{1}\nWith result: {2}\n\n",
                callerMethodName, dbCommand.CommandText, interceptionContext.Result);
        }
    }
}

Notice the clever use of CallerMemberNameAttribute to be able to print out the command type 😉

For this interceptor to be used, you need to register it in a specialised DbConfiguration class.

Custom database configuration class:

public class CustomDatabaseConfiguration : DbConfiguration
{
    public CustomDatabaseConfiguration()
    {
        AddInterceptor(new CustomSqlLogger());
    }
}

This configuration class is used automagically by Entity Framework.

Interceptors can also be injected via config file.

Configuration-based interceptor injection:

<entityFramework>
    <interceptors>
      <interceptor type="SQLLogger.CustomSqlLogger, SQLLogger"></interceptor>
    </interceptors>
</entityFramework>

Log output

This custom logging interceptor will produce the following output when running a sample application.

Scalar:

Intercepted ScalarExecuting:
SELECT Count(*)
FROM INFORMATION_SCHEMA.TABLES AS t
WHERE t.TABLE_SCHEMA + '.' + t.TABLE_NAME IN ('dbo.Departments','dbo.Employees')
    OR t.TABLE_NAME = 'EdmMetadata'
With result: 

Intercepted ScalarExecuted:
SELECT Count(*)
FROM INFORMATION_SCHEMA.TABLES AS t
WHERE t.TABLE_SCHEMA + '.' + t.TABLE_NAME IN ('dbo.Departments','dbo.Employees')
    OR t.TABLE_NAME = 'EdmMetadata'
With result: 2

The Scalar command has no result while executing, and returns the value 2 once finished.

Reader:

Intercepted ReaderExecuting:
SELECT 
    1 AS [C1], 
    [Extent1].[deptName] AS [deptName]
    FROM [dbo].[Departments] AS [Extent1]
With result: 

Intercepted ReaderExecuted:
SELECT 
    1 AS [C1], 
    [Extent1].[deptName] AS [deptName]
    FROM [dbo].[Departments] AS [Extent1]
With result: System.Data.SqlClient.SqlDataReader

This Reader command gives a SqlDataReader as a result to the query to retrieve all departments.

NonQuery:

Intercepted NonQueryExecuting:
CREATE TABLE [dbo].[Departments] (
    [departmentID] [int] NOT NULL IDENTITY,
    [deptName] [varchar](50),
    [deptFloor] [varchar](50),
    CONSTRAINT [PK_dbo.Departments] PRIMARY KEY ([departmentID])
)
With result: 0

Intercepted NonQueryExecuted:
CREATE TABLE [dbo].[Departments] (
    [departmentID] [int] NOT NULL IDENTITY,
    [deptName] [varchar](50),
    [deptFloor] [varchar](50),
    CONSTRAINT [PK_dbo.Departments] PRIMARY KEY ([departmentID])
)
With result: -1

This NonQuery command is executed by the Entity Framework the first time the application is started, to create the necessary tables.

Entity Framework tips

Disable entity tracking with extension AsNoTracking()

AsNoTracking() is an extension method that allows you to optimise your queries for large data sets by telling Entity Framework not to track the results of the query.

With this option, the results are streamed directly into memory and no additional processing is made and the entities are not added to the DbContext.

This means that entities retrieved with such a query cannot be updated since they are not know to the context. If you wish to modify and save some entities that were retrieved from a AsNoTracking() query, you first need to attach it to the context and set the correct state before doing so.

This option is especially useful when you are dealing with large quantities of data that you only want to read.

Say a company has a huge number of employees and has an overview page where all names are displayed:

IQueryable<string> query = db.Employees
                    .Select(e => e.lastName + " " + e.firstName)
                    .OrderBy(fullName => fullName)
                    .AsNoTracking();

Since we are only reading data, it makes sense to disable tracking for this query.

Execute stored procedures

When working with existing stored procedures (either legacy or by design), it is best practice to create corresponding methods in your DbContext subclass. The execution is made through ObjectContext.ExecuteFunction(), which you feed the name of the procedure as well as the list of required parameters.

Executing a stored procedure:

public partial class CompanyContext : DbContext
{
    public CompanyContext(): base("name=CompanyDb") { }

    // ...

    public virtual int UpdateEmployeeStoredProcedure(Nullable<int> businessEntityID, string jobTitle, Nullable<System.DateTime> hireDate)
    {
        var businessEntityIDParameter = businessEntityID.HasValue ?
            new ObjectParameter("BusinessEntityID", businessEntityID) :
            new ObjectParameter("BusinessEntityID", typeof(int));

        var jobTitleParameter = jobTitle != null ?
            new ObjectParameter("JobTitle", jobTitle) :
            new ObjectParameter("JobTitle", typeof(string));

        var hireDateParameter = hireDate.HasValue ?
            new ObjectParameter("HireDate", hireDate) :
            new ObjectParameter("HireDate", typeof(System.DateTime));

        return ((IObjectContextAdapter)this).ObjectContext.ExecuteFunction("uspUpdateEmployee", businessEntityIDParameter, jobTitleParameter, hireDateParameter);
    }
}

You need to cast the DbContext to IObjectContextAdapter because the implementation of ObjectContext in DbContext is explicit.

Execute custom SQL queries from Entity Framework

When you want precise control over a SQL query instead of relying on Entity Framework to generate it, you can create custom queries using DbContext.Database.SqlQuery(). The type T specifies which type Entity Framework should try to convert the results to.

Executing a custom SQL query:

public static void PrintEmployees(string firstNameToFind)
{
    using (var db = new CompanyContext())
    {
        DbRawSqlQuery<Employee> employeesSqlQuery = 
            db.Database.SqlQuery<Employee>("select top 42 * from Employees where firstName={0}",
              firstNameToFind);

        foreach (var employee in employeesSqlQuery)
        {
            Console.WriteLine(employee.firstName);
        }
    }
}

Summary

In this post, we saw four ways to debug queries generated by Entity Framework:

  • SQL Server profiler
  • using ToString() on the query object
  • logging database commands using DbContext.Database.Log
  • intercepting database commands by injecting a IDbCommandInterceptor

Additionally, we saw how to:

  • disable change tracking on queries with the extension method AsNoTracking()
  • call stored procedures using DbContext.ObjectContext.ExecuteFunction()
  • execute custom SQL queries with DbContext.Database.SqlQuery<T>()
  • Nice blog post.

    I wonder if it is possible to have “AsNoTracking()” per default and when you want update entities you explicitly specify it.

    The usual approach 😉
    1. Realize that we should optimize some performance
    2. Try to add “AsNoTracking”, watch and fail or hope and suceed…

    • Yes, it would make sense to only use change tracking when you actually need it 🙂

      Apparently you cannot disable it globally, but you could use a method to wrap all queries where you don’t need it. Or set it on the ObjectContext, as shown there:
      http://stackoverflow.com/questions/12726878/global-setting-for-asnotracking

      From what I heard from EF7, I get the impression that it does less things behind closed doors without asking you. You need to be more explicit in your code.

      Making implicit behaviours explicit, I like that 🙂

  • kiquenet kiquenet

    any `SerilogCommandInterceptor` using ***Serilog***? Sample for NLog: `NLogCommandInterceptor` for EF6 https://blog.oneunicorn.com/2013/05/14/ef6-sql-logging-part-3-interception-building-blocks ,