Programming Entity Framework

One of the big questions people have about Entity Framework's dynamically generated queries is "what does the store query look like?", immediately followed by "is that store query acceptable"?

There are a few ways to see what the store generated queries look like. One is to use ObjectQuery.ToTraceString. It's possible to use this method with LINQ to Entities queries as well, because  you can cast a L2E query to an ObjectQuery. The other way to see the generated store query is good old SqlProfiler, or whatever tool is available for your given database.

You can also test Entity SQL queries one at a time with the eSqlBlast tool that is on Code Gallery. This was written by Zlatko Michailov when he was the PM for Entity SQL. eSqlBlast has been an invaluable tool for me for testing my Entity SQL expressions.

But I'd rather not have to inspect the queries at run time and on a one-by-one basis. Instead, I wanted to have a log showing EDM queries paired with their resulting (or resultant, as the copy editor of my book has tried to train me to use) store queries. I suggested to one of my clients that they could then take this log file to the DBA and just keep track of when his or her face begins to turn crimson or steam begins coming from their ears when perusing the log. WIth this important feedback ;-), the developers can revisit the queries and see if they can improve on them, for example, in the case of certain LINQ or ESQL queries that produce nasty WHERE queries. "Nasty" in this case is a query that does not have proper search arguments, called "non-SARGable" by DBAs. (Thanks to Adam Machanic for explaining this to me last year.)  "WHERE substring(LastName,1)='A'" will cause the database to read through every row in a table examining the LastName field. "WHERE LastName LIKE 'A%'", on the other hand, is handled much more intelligently by the database.

By comparing these logs to SQL Profiler, we can also identify which queries are run very frequently and if they are really bad and there is no easy way to revise the client-side query to improve on them, this is a place where you may want to map to views and stored procs rather than directly to a table.

Because I will build this log file in the application, I am using ToTraceString

As far as I know, methods like explicit loads or Try/GetObjectByKey do not give us the opportunity to log either the query or the store command. Hopefully in a later version of EF, we'll have access to more events within EF's functionality.

The Log File

Creating a log file is actually not too complex, once you have figured out all of the working parts.

I want to store the results in an XML file so they can be easily accessed after the fact. I'll use LINQ to XML to build each log entry in the file.

The XML log file, containing a single example ESQL entry looks like this:

<?xml version="1.0" encoding="utf-8"?>
<QueryLog>
  <log Type="ESQL">
    <Expression>select value c from AdventureWorksLTEntities.Customers as c order by c.LastName</Expression>
    <StoreSQL>SELECT 
               [Extent1].[CustomerID] AS [CustomerID], 
               [Extent1].[NameStyle] AS [NameStyle], 
               [Extent1].[Title] AS [Title], 
               [Extent1].[FirstName] AS [FirstName], 
               [Extent1].[MiddleName] AS [MiddleName], 
               [Extent1].[LastName] AS [LastName], 
               [Extent1].[Suffix] AS [Suffix], 
               [Extent1].[CompanyName] AS [CompanyName], 
               [Extent1].[SalesPerson] AS [SalesPerson], 
               [Extent1].[EmailAddress] AS [EmailAddress], 
               [Extent1].[Phone] AS [Phone], 
               [Extent1].[PasswordHash] AS [PasswordHash], 
               [Extent1].[PasswordSalt] AS [PasswordSalt], 
               [Extent1].[rowguid] AS [rowguid], 
               [Extent1].[ModifiedDate] AS [ModifiedDate]
              FROM [SalesLT].[Customer] AS [Extent1]
              ORDER BY [Extent1].[LastName] ASC
    </StoreSQL>
  </log>
</QueryLog>

For each entry, I have an attribute that identifies the type as LINQ or ESQL as well as the actual expression and then the store expression. It's important to note that if you have appended First() or FirstOrDefault() to your query, that won't get picked up by ToTraceString() although it will be part of the actual query executed on the server.

Building a Log Entry

An EntitySQL expression is easily grabbed from an ObjectQuery using ObjectQuery.CommandText . This is the same whether you are using Entity SQL directly or the query is created with query builder methods.

I foolishly spent a lot of time digging around in the IQueryable.Expression to see how to build up a string from the various parts of the LINQ tree until it finally occurred to me to see what Expression.ToString() would return. Et voila, a very nice representation of the LINQ query. Here's an example:

value(System.Data.Objects.ObjectQuery`1[TestQueryLogging.Customer]).OrderBy(c => c.LastName)

My logging class has a constructor that takes either an ObjectQuery or an IQueryable as its argument. It then pulls the necessary details for logging out of the query and stores them in local variables.

    public QueryLogFile(IQueryable linqQuery)
    {
      _querytype = QueryType.LINQ;
      _linqQuery = linqQuery.Expression.ToString();
      _StoreSQL = ((ObjectQuery)linqQuery).ToTraceString();
      CreateLogEntry();
    }

    public QueryLogFile(ObjectQuery objQuery)
    {
      _querytype = QueryType.ESQL;
      _ESQL = objQuery.CommandText; 
      _StoreSQL = objQuery.ToTraceString();
      if (_ESQL != string.Empty) //if this was cast from LINQ, don't log  here
        CreateLogEntry();
    }

The CreateLogEntry method opens the XML log file, uses LINQ to XML to insert the new log entry and then saves the modified file.

  private void CreateLogEntry()
    {
      XElement logs = XElement.Load(@"logs\LogFile.xml");
      XElement newlog = new XElement("log", new XAttribute("Type", _querytype));
      if (_querytype == QueryType.LINQ)
        newlog.Add(new XElement("Expression", _linqQuery));
      else
        newlog.Add(new XElement("Expression", _ESQL));

      newlog.Add(new XElement("StoreSQL", _StoreSQL));
      logs.Add(newlog);
      logs.Save(@"logs\LogFile.xml");
    }

Calling the Logging utiity

Because the constructor of the logging class creates the log entry, you only need to instantiate a logging object, passing in a query.

var logger = new QueryLogFile(myQuery);

Using a wrapper class to call the utility for your queries

But there's a problem here. Do you really want to add this to every query in your application? Of course not.

In the latter part of my book, I introduced a class called the CommandExecutor which is a wrapper class for executing queries. Currently it is limited to queries that call ToList or First or FirstOrDefault and Get. I built it for a way to have common exception handling for queries without having to repeat the exception handlers with every single query that I'm executing. If your code needs to enumerate over a query, the task is much more complicated. You would have to pass in not only the query, but a delegate of the code to be run within the enumeration. I'll tackle that another day.

In my applications, unless I want to enumerate over streamed results, I almost always call ToList() or on of the other methods to force query execution so that I don't have to worry about unwittingly re-executing a query. Therefore, the CommandExecutor handles a large portion of my queries.

There are overloads that will accept either LINQ to Entities or ObjectQuery. Only the ObjectQuery's method provides the common exception handling and logging. The method that takes a LINQ query casts the query to ObjectQuery, then passes it to the other overload.

Here is part of the ExecuteList() method that takes the ObjectQuery parameter.

   public TEntity ExecuteFirstorDefault<TEntity>(ObjectQuery<TEntity> objectQuery)
    {
      try
      {
        var logger = new QueryLogFile(objectQuery);
        return objectQuery.FirstOrDefault(); 
      }
      catch (EntitySqlException ex)
      {
        throw ex; //TODO: Replace with handling code
      }

      //more catch statements follow this

Summary

While this solution doesn't give me 100% coverage of my queries, it gets me pretty far. If you only want to see the store commands, you are finished. If you want to evaluate them for performance and frequency, then you can probably do some text matching against SqlProfiler logs and identify which queries are creating the worst problem. There's much more to do here, for example, identifying where in the application the query is coming from.

I envision a tool by a company like Red Gate sometime in the future since they are so adept at working inside of SQL and inside of .NET code with their various profiling tools. Maybe Red Gate will get a trackback on this blog post and agree! :-)