Tracing SQL Statements generated by Entity Framework

The DataContext of Linq2Sql provides a Log property that one can assign a TextWriter to retrieve the text of the SQL statements generated by Linq. The ObjectContext of Entity Framework does not contain such an easy way to trace generated SQL statements.

An MSDN blog provides a solution in the form of an Entity Framework provider which simply wraps the existing EF data provider.

Integration into an existing project is pretty simple and straight forward (see detailed discussion on MSDN):

• Register Provider Factories in web.config or app.config
• Derive a class (ExtendedEntities) from the generated Entities class
• Use the ExtendedEntities class throughout the code

To be able to switch between logging and non-logging code, I found it helpful to modify this approach a bit.

First, all “extended” functionality is activated in the code using a #define symbol. If the symbol is defined, there will also be a compiler warning to notify the developer whether the build is for debug or production.

Second, the tracing functionality will only be activated if the config file contains an AppSetting named “EFTraceDir”.

Next, I replaced the entity context creation code from

using (var context = new Entities())

to a factory pattern

using (var context = Entities.Create())

with the method

static Entities Create()
{
#if trace
  if (TraceEnabled)
  {
    ExtendedEntities context = new ExtendedEntities();
    context.CommandFinished += EFCommandFinished;
    return context;
  }
#endif
  return new Entities();
}

CommandFinished is an event defined by the EFTracingProvider, and will be use to log the generated SQL to files.

Statements generated by Linq do not have a name, so it would be hard to associate any generated SQL statement with the original Linq definition.

Thus we need to find out where in the code the statement was invoked.

A quick search on StackOverflow resulted in the .Net classes StackTrace and StackFrame. This little routine list the whole stack and returns the class name causing the invocation, which corresponds to the aspx page name (in case you want to trace an ASP.Net application):

private static StringBuilder ListStack(out string sType)
{
  StringBuilder sb = new StringBuilder();
  sType = "";

  StackTrace st = new StackTrace(true);
  foreach (StackFrame f in st.GetFrames())
  {
    MethodBase m = f.GetMethod();
    if (f.GetFileName() != null)
    {
      sb.AppendLine(string.Format("{0}:{1} {2}.{3}",
        f.GetFileName(), f.GetFileLineNumber(),
        m.DeclaringType.FullName, m.Name));

      if (!string.IsNullOrEmpty(m.DeclaringType.Name))
        sType = m.DeclaringType.Name;
    }
  }

  return sb;
}

Omitting the condition (f.GetFileName() != null) will also list the .Net system assemblies and methods.

Putting it all together, we simply write the command, its parameters, and the stack trace into a file. The file is named after the aspx page name (i.e. the bottom-most type name on the stack), the statement length, and the statement ID.

private static void EFCommandFinished(object sender, CommandExecutionEventArgs e)
{
  string sType;
  StringBuilder sb = ListStack(out sType);

  System.IO.File.WriteAllText(
    Path.Combine(EFTraceDir, string.Format("{2} {0:D9} {1:D9}.txt",
      e.Command.CommandText.Length, e.CommandId, sType)),
    string.Format("{0}\r\n{1}\r\n{2}\r\n",
      e.Duration, e.ToTraceString(), sb.ToString()));
}

Choice of the file name pattern makes it easy to sort files by originating aspx name and statement length.

Multiple files with equal length (as shown in the filename) indicate that the same statement is used several times, a good indicator to check database access code and cache results.

The generated SQL also gives you an idea of how your Linq queries are translated, and whether you need to optimize them or rewrite them to a) reduce statement length and b) reduce the amount of selected data.

private static void EFCommandFinished(object sender, CommandExecutionEventArgs e)
{
string sType;
StringBuilder sb = ListStack(out sType);

System.IO.File.WriteAllText(
Path.Combine(EFTraceDir, string.Format(“{2} {0:D9} {1:D9}.txt”, e.Command.CommandText.Length, e.CommandId, sType)),
string.Format(“{0}\r\n{1}\r\n{2}\r\n”, e.Duration, e.ToTraceString(), sb.ToString()));
}