Simple and Easy Entity Framework SQL Tracing

There’s an easy way to add tracing to an application, but Entity Framework brings some special challenges. ObjectQuery.ToTraceString does allow tracing of SQL SELECT commands, but there’s no built-in way to trace database updates.

However, there is an Entity Framework Tracing Provider that allows this. Follow the quick-start instructions on the home page, and you’ll be off in no time!

Here’s a few tests using SQL Server Compact Edition to access the Northwind sample database. This code:

using (var db = new NorthwindContext())
{
    MessageBox.Show(db.Orders.Count(x => x.Order_Date < DateTime.Now).ToString());
}

will result in this trace:

EntityFramework.NorthwindEntities Information: 0 : Executing 1: SELECT [GroupBy1].[A1] AS [C1] FROM ( SELECT COUNT(1) AS [A1] FROM [Orders] AS [Extent1] WHERE [Extent1].[Order Date] < ( CAST( GetDate() AS datetime)) ) AS [GroupBy1]
EntityFramework.NorthwindEntities Information: 0 : Finished 1 in 00:00:00.0466592: [DbDataReader(C1:Int)]

Note that the total time taken by the query is included in the finishing trace. Another interesting tidbit is that DateTime.Now is not evaluated on the client side; rather, the SQL statement includes a call to GetDate.

Here’s some code that deletes an order:

using (var db = new NorthwindContext())
{
    db.Orders.DeleteObject(db.Orders.OrderBy(x => x.Order_Date).First());
    db.SaveChanges();
}

resulting in this trace:

EntityFramework.NorthwindEntities Information: 0 : Executing 2: SELECT TOP (1) [Extent1].[Order ID] AS [Order ID], [Extent1].[Customer ID] AS [Customer ID], [Extent1].[Employee ID] AS [Employee ID], [Extent1].[Ship Name] AS [Ship Name], [Extent1].[Ship Address] AS [Ship Address], [Extent1].[Ship City] AS [Ship City], [Extent1].[Ship Region] AS [Ship Region], [Extent1].[Ship Postal Code] AS [Ship Postal Code], [Extent1].[Ship Country] AS [Ship Country], [Extent1].[Ship Via] AS [Ship Via], [Extent1].[Order Date] AS [Order Date], [Extent1].[Required Date] AS [Required Date], [Extent1].[Shipped Date] AS [Shipped Date], [Extent1].[Freight] AS [Freight] FROM [Orders] AS [Extent1] ORDER BY [Extent1].[Order Date] ASC
EntityFramework.NorthwindEntities Information: 0 : Finished 2 in 00:00:00.0027257: [DbDataReader(Order ID:Int, Customer ID:NVarChar, Employee ID:Int, Ship Name:NVarChar, Ship Address:NVarChar, Ship City:NVarChar, Ship Region:NVarChar, Ship Postal Code:NVarChar, Ship Country:NVarChar, Ship Via:Int, Order Date:DateTime, Required Date:DateTime, Shipped Date:DateTime, Freight:Money)]
EntityFramework.NorthwindEntities Information: 0 : Executing 3: delete [Orders] where ([Order ID] = @0) { @0=[Int32,0,Input]10000 }
EntityFramework.NorthwindEntities Information: 0 : Finished 3 in 00:00:00.0482807: 1 rows affected

As expected, the first command executes a single-row SELECT, followed by a DELETE that affects a single row. Note the use of the parameterized deletion query.

Unfortunately, the Entity Framework Tracing Provider does not support everything; in particular, direct database commands (e.g., ExecuteStoreCommand) are not supported.