December 2010

Volume 25 Number 12

Data Points - Profiling Database Activity in the Entity Framework

By Julie Lerman | December 2010

In last month’s Data Points column (msdn.microsoft.com/magazine/gg309181), I wrote about profiling the performance of the Entity Framework against SQL Azure. This month, I look at a different type of profiling—query profiling—to see what queries and commands are being executed on the database in response to queries and other data access activities in the Entity Framework.

One of the Entity Framework’s prime capabilities is command generation for executing database queries as well as inserts, updates and deletes. This is a huge benefit for many developers, although there will always be an ongoing debate about the quality of SQL generated by object-relational mapping (ORM) tools versus SQL handwritten by experts (I won’t be engaging in that debate in this article). And for the most part, the SQL that’s generated is pretty good, especially considering that it has to be constructed dynamically in a generic way, regardless of how creative you get with your LINQ to Entities or Entity SQL query expressions.

Although a lot of attention was paid to improving command generation in the Entity Framework 4, it’s still important to be aware of what’s happening in your database. The quality of the generated store query is only part of the story. You may be writing code that creates extended database execution times or an unusual number of trips to the database. These are critical things to be aware of when profiling your application.

For the first few years of the Entity Framework’s life, there was nothing available outside of database-profiling tools such as SQL Profiler, which, while informative, requires a lot of configuring and mining if you want to view the results in an easy-to-digest manner. Following are a variety of options for query profiling the Entity Framework beyond the database-profiling tools.

The Entity Framework ObjectContext.ToTraceString Method

The Entity Framework API (3.5 and 4) provides a single method for inspecting queries at run time, ToTraceString, which is useful but only provides information on a subset of the calls made to the database. ToTraceString is a method of ObjectQuery, so if you’re writing a LINQ to Entities query, you must first cast the query to an ObjectQuery before calling ToTraceString. Here’s an example:

var query = from c in context.Customers where c.CustomerID == 3 select c;
var objectQuery=query as System.Data.Objects.ObjectQuery;
Console.WriteLine(objectQuery.ToTraceString());

This outputs the following string:

SELECT
[Extent1].[CustomerID] AS [CustomerID],
[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].[ModifiedDate] AS [ModifiedDate],
[Extent1].[TimeStamp] AS [TimeStamp]
FROM [SalesLT].[Customer] AS [Extent1]
WHERE 3 = [Extent1].[CustomerID]

Notice that the code sample doesn’t execute the query. Nor does ToTraceString, which causes the query to be processed (transformed to a store query) by the Entity Framework with help from the database provider, System.Data.SqlClient, but doesn’t force the query to be executed on the database.

You can use ToTraceString only with explicitly defined queries. Therefore, you can’t use it to see queries executed as a result of deferred loading with the Load method or lazy loading. Nor can you use it to inspect activity such as inserts, updates, deletes or stored procedure execution.

Finally, it’s important to note that you can’t easily get the results of ToTraceString into a debug process, by, for example, creating a debugger visualizer. That would require ObjectQuery to be serializable, which it’s not.

Profiling with Visual Studio 2010 IntelliTrace

IntelliTrace is available in Visual Studio 2010 Ultimate but not the lesser versions. IntelliTrace captures database activity, including that which is triggered by the Entity Framework, but it doesn’t display the parameter values that were sent with the command.

Following is some code that performs the following tasks:

1. Executes a query of 10 customers
2. Lazy loads the orders for the first returned customer
3. Disables lazy loading
4. Explicitly loads the orders for the second returned customer
5. Modifies a customer
6. Sends the changes to the database with the SaveChanges method
7. Executes a function that I’ve mapped to a stored procedure in an Entity Data Model

var query = from c in context.Customers select c;
var custList = query.Take(10).ToList();
Customer custFirst = custList[0];
int orderCount = custFirst.Orders.Count; 
context.ContextOptions.LazyLoadingEnabled=false;
Customer custSecond = custList[1];
custSecond.Orders.Load(); 
custSecond.ModifiedDate = DateTime.Now;
context.SaveChanges(); 
ObjectResult<PartialOrderDetails> orders= 
  context.GetCustomerOrdersForId(custList[2].CustomerID);

When run, this code will force the execution of three SELECT statements, an UPDATE statement and then an Execute command for the stored procedure in the database.

Looking at the IntelliTrace screenshot in Figure 1, you can see all five of these commands.

Figure 1 A Series of Database Commands Displayed in the Visual Studio IntelliTrace Display

However, expanding one of these items, as shown in Figure 2, shows that the command is there but the parameters are not.

Figure 2 A Detailed Select Statement Collected by the Visual Studio 2010 IntelliTrace Feature

Therefore, if you want to see the database activity including parameters, you’ll need to use some type of external profiler.

The EFTracingProvider on MSDN Code Gallery

Jarek Kowalski wrote the EFTracingProvider when he was on the Entity Framework team at Microsoft. There’s a version for the Microsoft .NET Framework 3.5 and one for the .NET Framework 4.

To use the EFTracingProvider, you’ll need to build a wrapper around the ObjectContext class, AWEntities, and use that in place of AWEntities. This extended class provides tracing methods, such as Log, that you can use to log context activities. There’s an example of the required class wrapper included with the EFTracingProvider download. You’ll also find the relevant code in the download for this article (code.msdn.microsoft.com/mag201012DataPoints). Additionally, you need to add two DbProviderFactories settings in the application’s config file. With all of this in place, you can then instantiate the extended context and begin logging.

Here’s an example that creates a text file to capture the log events and then uses the TracingProvider.Log method to log all of the activities:

using (TextWriter logFile = File.CreateText("sqllogfile.txt"))
{
  using (var context = new ExtendedAWEntities())
  {
    context.Log = logFile;
    var query = from c in context.Customers select c;
    var custList = query.Take(10).ToList();
  }
  Console.WriteLine(File.ReadAllText("sqllogfile.txt"));
}

Using the TracingProvider wrapper and the ExtendedAWEntities context class, I reran the same set of code as in the previous IntelliTrace example.

All five database commands were logged and each command was logged with its relevant parameters.

Figure 3, as an example, shows the command sent as a result of the lazy load where the value of the EntityKeyValue1 parameter is specified after the command is listed.

Figure 3 A Command Captured by the EFTracingProvider

SELECT
[Extent1].[SalesOrderID] AS [SalesOrderID],
[Extent1].[OrderDate] AS [OrderDate],
[Extent1].[DueDate] AS [DueDate],
[Extent1].[OnlineOrderFlag] AS [OnlineOrderFlag],
[Extent1].[SalesOrderNumber] AS [SalesOrderNumber],
[Extent1].[PurchaseOrderNumber] AS [PurchaseOrderNumber],
[Extent1].[AccountNumber] AS [AccountNumber],
[Extent1].[CustomerID] AS [CustomerID],
[Extent1].[BillToAddressID] AS [BillToAddressID],
[Extent1].[CreditCardApprovalCode] AS [CreditCardApprovalCode],
[Extent1].[SubTotal] AS [SubTotal],
[Extent1].[Comment] AS [Comment],
[Extent1].[ModifiedDate] AS [ModifiedDate],
[Extent1].[ShipDate] AS [ShipDate]
FROM [SalesLT].[SalesOrderHeader] AS [Extent1]
WHERE [Extent1].[CustomerID] = @EntityKeyValue1
-- EntityKeyValue1 (dbtype=Int32, size=0, direction=Input) = 1

The EFTracingProvider is simple to implement and provides you with all of the database commands generated by your Entity Framework code as raw text. You can also subscribe to the tracing events: CommandExecuting, CommandFinished and CommandFailed on the context. These give you access to the raw DbCommand just before and after it gets executed so you can analyze or log additional details.

You can download the EFTracingProvider—along with its companion, the EFCachingProvider, and a sample solution, the EFProviderWrapperDemo, which explores all of these features—for free from the MSDN Code Gallery (code.msdn.microsoft.com/EFProviderWrappers).

Third-Party Profilers

You may, however, wish to go beyond the raw text of the EFTracingProvider’s log file. You can leverage and learn from the code in those log files or take advantage of two tools that have already done the work for you. There are two third-party tools for profiling Entity Framework queries: Hibernating Rhinos Entity Framework Profiler and Huagati Query Profiler.

Additionally, LINQPad, which is focused on allowing you to test query expressions outside of your application, displays SQL for the expressions you’re executing. Although this is an indispensable tool for anyone writing LINQ against a large variety of providers, it doesn’t allow you to profile the queries generated by your application, and therefore I won’t explore it further in this column.

Entity Framework Profiler (EF Prof) is part of the Hibernating Rhinos UberProf family of profilers (hibernatingrhinos.com/products/UberProf). There are also profilers for nHibernate, Hibernate and LINQ to SQL. A fifth profiler, LLBLGen Pro, was in beta at the time of writing. EF Prof combines the existing intellectual property derived from the other UberProf tools with some ideas gleaned from the EFTracingProvider. At its simplest, you can add a single line of code to your application to enable it to talk to EF Prof’s engine and have the results reported in the EF Prof client application:

HibernatingRhinos.Profiler.  
    Appender.EntityFramework.
    EntityFrameworkProfiler.Initialize

Database activity is grouped by ObjectContext instance. In Figure 4, you can see that there are two ObjectContext instances displayed—that’s because I ran my example code twice. 

Figure 4 The EF Prof Query Profiler UI

Also in Figure 4, on the right, you can see a preview of each of the database calls for the selected context instance. It appears that there’s an extra SELECT being called after the UPDATE command. This is, in fact, part of the command that’s sent with SaveChanges as the Entity Framework is ensuring that the Customer row’s updated TimeStamp field is returned to the customer instance.

As you highlight a SQL statement in the UI, you can see the complete SQL in the lower screen along with a reference to the fact that the value—5 in this case—was passed in as a parameter, @EntityKeyValue1.

EF Prof also allows you to see the resultant rows from the query, and even the database query plan. The Stack Trace tab, shown in Figure 5, lets you see how the application came to execute a particular command and even lets you jump directly to that line of code in Visual Studio.

Figure 5 The EF Prof Stack Trace Lets You Jump to the Code that Executed the Selected Database Command

EF Prof is able to capture all of an application’s Entity Framework activity and presents it in an easy-to-navigate UI along with some great bells and whistles—such as the query plan view—and links back to the executing code. A standard license to EF Prof is $305 with discounts for multiple licenses and a subscription plan. EF Prof works with any of the Entity Framework data providers and therefore isn’t limited to SQL Server. It works with the .NET Framework versions 3.5 and 4.

Huagati Query Profiler, originally called L2S Profiler, was updated in November to add support for the Entity Framework 4. You can also use it to profile LINQ to SQL and LLBLGen Pro, but it currently only works with SQL Server.

Implementing the Query Profiler is a matter of referencing the profiler’s assembly (Huagati.EFProfiler.dll) in your application and adding two new constructors, plus some additional logic to your ObjectContext class in a partial class. Figure 6 shows the partial class I’ve created for my AWEntities class.

Figure 6 The Partial Class to Use with Huagati Query Profiler

string profilerOutput =
      System.IO.Path.Combine(System.Environment.GetFolderPath(
        Environment.SpecialFolder.Personal),
      @"EFProfiler\Samples");
    _profiler=new HuagatiEFProfiler.EFProfiler(this, profilerOutput, null, 
      HuagatiEFProfiler.ExecutionPlanMode.Actual, false);
   _profiler.LogError += EFProfiler_LogError;
  }
}

The EFProfiler.GetConnection method hooks into the database to track its activity. You can learn more about various settings you can use when instantiating the EFProfiler on the Huagati Web site.

The profiler collects its data and outputs it to a file in the designated folder. You can then open that file up in the profiler’s Log Explorer, shown in Figure 7.

Figure 7 The Huagati Entity Framework Query Profiler UI

As you can see in Figure 7, all five database requests were collected. The Update command is combined with its SELECT command to return the TimeStamp, which is exactly how the command is sent to the database.

The Log Explorer shown in Figure 7 displays the relevant lines from the SQL Server SQL Profiler data. As with EF Prof, you can see the query with its parameters, link back to the relevant code lines in your application from the Stack view, view the execution plan and see some statistics about the queries.

The database activity for each context instance is stored in a separate log file, so the Log Explorer will only display one set of commands at a time. The Settings allow you to color-code alerts highlighting unusual activity levels such as noticeably or even alarmingly long execution times.

The Query Profiler UI isn’t as slick as the EF Prof UI, and you need to make a slightly greater investment in your code (adding logic to each ObjectContext in your application). But the components are distributable, which means that you can collect profiler information for apps running in your client’s environment. Also, it doesn’t have as many analysis options as EF Prof. But the $20 Standard and $40 Professional sticker price (which includes all three profilers), may make up for these differences for many developers. Keep in mind that the Huagati Entity Framework Profiler was still in beta when I did my exploration and that it only works with SQL Server, as opposed to the ability of EF Prof to work with any of the available ADO.NET Data Providers that support the Entity Framework.

 An introduction to Hugati’s Entity Framework support can be found at tinyurl.com/26cfful. At the end of that blog post you’ll find a link to download the beta version, 1.31.

The Right Tool for the Job

I’m a big believer of using the right tool for the job, and that it’s wasteful to try to squeeze functionality out of the Visual Studio 2010 box when there are other great tools available. In this column, you’ve seen an array of tools built into the Entity Framework APIs and Visual Studio 2010, an extension that will provide you with raw data and two third-party tools that perform not only the task of data collection, but presentation as well. Whichever one of these paths you choose, even if you simply use SQL Profiler, you shouldn’t take your database for granted when profiling your application.

Julie Lerman is a Microsoft MVP, .NET mentor and consultant who lives in the hills of Vermont. You can find her presenting on data access and other Microsoft .NET topics at user groups and conferences around the world. She blogs at thedatafarm.com/blog and is the author of the highly acclaimed book, “Programming Entity Framework” (O’Reilly Media, 2010). Follow her on Twitter.com: julielerman.

Thanks to the following technical expert for reviewing this article: Jarek Kowalski