Tallan Blog

Tallan’s Experts Share Their Knowledge on Technology, Trends and Solutions to Business Challenges

Taking a Look at Entity Framework Queries pt 1 (.NET Framework)

If you aren’t familiar, Entity Framework is a powerful open-source object-relational mapping (ORM) framework. Its initial release was back in 2008, so it has grown and evolved quite a bit. I have been using it now, very regularly, for about four years and just wanted to bring to light some tips and the missteps that I have encountered during that time.

I think the most important thing when using EF(Entity Framework) is to be aware of the work it is doing on your behalf.  The best way to see what EF is doing is to simply log it, and for me, that means the output window in Visual Studio, not the database, as you will see, EF does a lot.  So, that being said, it is actually much easier to do than you might expect, and in my mind, there are really two flavors of implementation that you can choose from. (Note: there are likely many more than two, these are just what I do)

Version 1: No implementation – I just want to see what’s happening this one time

Simply put, if you’re just trying to debug a slow query and don’t want to make a real code change, then this is likely a pretty good solution.  All you need to do is add a Console.WriteLine() or whatever means you want for printing information to be called on a non-yielded EF query.

So what does that mean exactly? 

Generally speaking, when data is fetched using EF, the common practice is to grab your entities through the DbContext, and then possibly include subitems, and then generally convert the item .ToList().

I created a sample app with the idea of Users, Time Entries, Expense Entries, and few other quick associations for these examples, so the entities will follow that paradigm.  This is not from any type of legitimate production application though.

Example:

//plausible implementation
public IEnumerable<SystemUser> Get()
{
    return _ctx.SystemUsers
               .Include(x => x.TimeEntries)
               .ToList();
}

So, what’s important to know and understand here, is that until the .ToList() is appended to the query, the query is not executed and there is no attempt to materialized the entities.  That being said, we have an opportunity to investigate what EF will do to do that work.  Looking below, this simple modification gives us the ability to see the query before it executes.

//changed to this
public IEnumerable<SystemUser> Get()
{
   var query = _ctx.SystemUsers
                   .Include(x => x.TimeEntries);
   Console.WriteLine(query); // for my demo - I am printing to the console
   return query.ToList();
}

Note: As an alternative, you can also do the same with no write line and just place a break point on the return and just query.ToString() in the immediate window.

Now as the method executes we can see the query it creates to fetch the data.

In the case of my app and the EF code above:


SELECT
    [Project1].[SystemUserId] AS [SystemUserId],
    [Project1].[SomeProperty] AS [SomeProperty],
    [Project1].[SomeOtherProperty] AS [SomeOtherProperty],
    [Project1].[C1] AS [C1],
    [Project1].[TimeEntryId] AS [TimeEntryId],
    [Project1].[SomeProperty1] AS [SomeProperty1],
    [Project1].[SomeOtherProperty1] AS [SomeOtherProperty1],
    [Project1].[SystemUserId1] AS [SystemUserId1],
    [Project1].[ClientProjectId] AS [ClientProjectId]
    FROM ( SELECT
        [Extent1].[SystemUserId] AS [SystemUserId],
        [Extent1].[SomeProperty] AS [SomeProperty],
        [Extent1].[SomeOtherProperty] AS [SomeOtherProperty],
        [Extent2].[TimeEntryId] AS [TimeEntryId],
        [Extent2].[SomeProperty] AS [SomeProperty1],
        [Extent2].[SomeOtherProperty] AS [SomeOtherProperty1],
        [Extent2].[SystemUserId] AS [SystemUserId1],
        [Extent2].[ClientProjectId] AS [ClientProjectId],
        CASE WHEN ([Extent2].[TimeEntryId] IS NULL) THEN CAST(NULL AS int) ELSE 1 END AS [C1]
        FROM  [dbo].[SystemUser] AS [Extent1]
        LEFT OUTER JOIN [dbo].[TimeEntry] AS [Extent2] ON [Extent1].[SystemUserId] = [Extent2].[SystemUserId]
    )  AS [Project1]
    ORDER BY [Project1].[SystemUserId] ASC, [Project1].[C1] ASC

So, will this support all of my needs?  Probably not, and here’s why.

Some LINQ operations implicitly yield the result (Example: .FirstOrDefault()), and by omitting them you completely change the underlying SQL.

If you need full coverage including those types of operations, then you should go with option #2

Version 2: DbCommandInterception – aka. Show me everything

This approach does have an implementation but gives you the benefit of seeing all the calls EF makes all the time and you need no change to existing EF calls.

There are a few pieces to the puzzle.  The first is an implementation of the IDbCommandInterceptor, which will do the actual logging of the calls.  IDbCommandInterceptor has six methods needing implementation.

  1. NonQueryExecuted
  2. NonQueryExecuting
  3. ReaderExecuted
  4. ReaderExecuting
  5. ScalarExecuted
  6. ScalarExecuting

These will be hit automatically if the interceptor is properly placed in the EF pipeline.  That being said, how do we do it?

The next piece (well, the way I am doing it) is a custom DbConfiguration implementation, which actually only has a constructor, which only adds the custom interceptor to itself.

The last piece is telling our DbContext to use the custom DbConfiguration.  There are a few ways to do this, and it will make sense to explore them so that you can make the right decision for how often the custom interception lives in the codebase – ie. should it only be for development?

Below is my implementation of the first two pieces, and then I will quickly illustrate how to connect them.

class EFCommandInterceptor : IDbCommandInterceptor
{
    public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        LogInfo("NonQueryExecuted", interceptionContext.IsAsync, command.CommandText);
    }

    public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) { }

    public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<System.Data.Common.DbDataReader> interceptionContext)
    {
        LogInfo("ReaderExecuted", interceptionContext.IsAsync, command.CommandText);
    }

    public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<System.Data.Common.DbDataReader> interceptionContext) { }

    public void ScalarExecuted(System.Data.Common.DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        LogInfo("ScalarExecuted", interceptionContext.IsAsync, command.CommandText);
    }

    public void ScalarExecuting(System.Data.Common.DbCommand command, DbCommandInterceptionContext<object> interceptionContext) { }

    private void LogInfo(string command, bool isAsync, string commandText)
    {
        Console.WriteLine($"  ------------------------------ INTERCEPTED ON ----------------------------------");
        Console.WriteLine($"  -------------- {command} running {(isAsync ? "asynchronously ---" : "not asynchronously ")}-----------------------");
        Console.WriteLine($"  --------------------------------------------------------------------------------");
        Console.WriteLine($"");
        Console.WriteLine($"  {commandText}");
        Console.WriteLine($"");
        Console.WriteLine($"  ----------------------------------------------------------------------------------");
        Console.WriteLine($"  --------------------------- END OF INTERCEPTION ----------------------------------");
        Console.WriteLine($"  ----------------------------------------------------------------------------------");
        Console.WriteLine($"");
        Console.WriteLine($"");
    }
}

Note: I did not implement the “executing” methods as the printout will become very redundant

public class DemoLoggingConfiguration : DbConfiguration
{
    public DemoLoggingConfiguration()
    {
        this.AddInterceptor(new EFCommandInterceptor());
    }
}

There are three ways that I found (there may and likely is more) to bind the configuration to the DbContext.

  1. Decorate the DbContext with an attribute
    [DbConfigurationType(typeof(DemoLoggingConfiguration))]
    public class DemoContext : DbContext
  1. Configure it in XML via the web.config – no example, but I can send you a link if you want to see it
  2. Set it in the application startup – this is what I did and seemed to make sense to me as I could write code to check what version of the app is running and only use it if Development.  In my startup I have the line.
    DbConfiguration.SetConfiguration(new DemoLoggingConfiguration());

Alright, now all of the EF Queries will be logged to the console as the app runs. Below I will display my app’s EF log, but beforehand I will show how simple the app is.

class Program
{
    static void Main(string[] args)
    {
        DbConfiguration.SetConfiguration(new DemoLoggingConfiguration());
        var ctx = new DemoContext();
        var repo = new BaseObjectRepository(ctx);
        repo.Get();
        Console.ReadLine();
    }       
}

So all I am doing is creating a new context and making the repo, then calling .Get() which is the call from earlier in the blog, then finally .ReadLine() so the console doesn’t close.
Here is the output of all of the EF work.

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ReaderExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  select cast(serverproperty('EngineEdition') as int)

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ScalarExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  IF db_id(N'EFDemo') IS NOT NULL SELECT 1 ELSE SELECT Count(*) FROM sys.databases WHERE [name]=N'EFDemo'

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ScalarExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

SELECT Count(*)
FROM INFORMATION_SCHEMA.TABLES AS t
WHERE t.TABLE_SCHEMA + '.' + t.TABLE_NAME IN ('dbo.Attachment','dbo.ExpenseEntry','dbo.ClientProject','dbo.SystemUser','dbo.TimeEntry')
    OR t.TABLE_NAME = 'EdmMetadata'

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ReaderExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  SELECT
    [GroupBy1].[A1] AS [C1]
    FROM ( SELECT
        COUNT(1) AS [A1]
        FROM [dbo].[__MigrationHistory] AS [Extent1]
        WHERE [Extent1].[ContextKey] = @p__linq__0
    )  AS [GroupBy1]

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ReaderExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  SELECT
    [GroupBy1].[A1] AS [C1]
    FROM ( SELECT
        COUNT(1) AS [A1]
        FROM [dbo].[__MigrationHistory] AS [Extent1]
    )  AS [GroupBy1]

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ReaderExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  SELECT TOP (1)
    [Extent1].[Id] AS [Id],
    [Extent1].[ModelHash] AS [ModelHash]
    FROM [dbo].[EdmMetadata] AS [Extent1]
    ORDER BY [Extent1].[Id] DESC

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

  ------------------------------ INTERCEPTED ON ----------------------------------
  -------------- ReaderExecuted running not asynchronously -----------------------
  --------------------------------------------------------------------------------

  SELECT
    [Project1].[SystemUserId] AS [SystemUserId],
    [Project1].[SomeProperty] AS [SomeProperty],
    [Project1].[SomeOtherProperty] AS [SomeOtherProperty],
    [Project1].[C1] AS [C1],
    [Project1].[TimeEntryId] AS [TimeEntryId],
    [Project1].[SomeProperty1] AS [SomeProperty1],
    [Project1].[SomeOtherProperty1] AS [SomeOtherProperty1],
    [Project1].[SystemUserId1] AS [SystemUserId1],
    [Project1].[ClientProjectId] AS [ClientProjectId]
    FROM ( SELECT
        [Extent1].[SystemUserId] AS [SystemUserId],
        [Extent1].[SomeProperty] AS [SomeProperty],
        [Extent1].[SomeOtherProperty] AS [SomeOtherProperty],
        [Extent2].[TimeEntryId] AS [TimeEntryId],
        [Extent2].[SomeProperty] AS [SomeProperty1],
        [Extent2].[SomeOtherProperty] AS [SomeOtherProperty1],
        [Extent2].[SystemUserId] AS [SystemUserId1],
        [Extent2].[ClientProjectId] AS [ClientProjectId],
        CASE WHEN ([Extent2].[TimeEntryId] IS NULL) THEN CAST(NULL AS int) ELSE 1 END AS [C1]
        FROM  [dbo].[SystemUser] AS [Extent1]
        LEFT OUTER JOIN [dbo].[TimeEntry] AS [Extent2] ON [Extent1].[SystemUserId] = [Extent2].[SystemUserId]
    )  AS [Project1]
    ORDER BY [Project1].[SystemUserId] ASC, [Project1].[C1] ASC

  ----------------------------------------------------------------------------------
  --------------------------- END OF INTERCEPTION ----------------------------------
  ----------------------------------------------------------------------------------

I’d bet that you wouldn’t have expected all of the earlier queries to execute before the actual .Get(), but they do, and it is worth noting those only happen directly before the first communication with the db.

I’m going to end here for step one. The goal of this was to simply raise awareness of what work EF is doing, so I challenge you to take a look. For the continuation, I am going to look at the effect of LINQ operators on the queries EF generates, and I will be using this sample to do it.

Thanks for the read.


Click Here to learn more about Tallan or see us in person at one of many Events!

Share this post:

No comments

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

\\\