DbProvider Profiler using WCF and DbProviderFactory Injection: Part II of IV

• Download source code - 83.55 KB

Introduction

In a professional project, we are using Entity Framework as an ORM provider for our application. On several occasions, we want to know what SQL query some LINQ query produced. This mostly is the case when a particular query is very slow, returns unexpected results, etc. To 'debug' a LINQ query, we could just use the cool new feature of VS 2010 (Ultimate), IntelliTrace. With this toolwindow, we can inspect which query is run at a given point in time. This is great when we would have an Ultimate license for VS2010, which we unfortunately do not have.

The second negative point about Intellitrace is that is doesn't tell us much about the executed query's performance. Did it take 500ms to run, or 5ms? We just don't know.

Wait a sec! Why don't you just use the SQL profiler software then? Well, I suggest you all try to debug a EF Query using the SQL-Profiler. It's just a pain in the ****.

Now, that's why I decided to look for a solution myself, I tried to keep it as basic, and simple as I could, so don't look for over-engineering here!

This will be a series of articles, I will try to keep an index here, so you can find the different parts easier.

Index

• Part I of IV: Overriding default DbProvider implementations with our own Proxies
• Part II of IV: Creating profiling information in our ProxyDbxxx classes
• Part III of IV: Connecting our code to the outside world: WCF
• Part IV of IV: Creating a simple VS Toolwindow to show Profiling output

Creating Proxy Classes

First of all, we need more information if we want to really profile anything. So the following classes will be wrapped in a Proxy:

• DbCommand
• DbConnection
• DbDataAdapter
• DbCommandDefinition

These classes, in particular DbConnection and DbCommand, will provide us with enough information to begin profiling Queries sent to the SQL backend. What we always do is keep a reference to the proxied object in our wrapper classes, so we can forward method calls, property getters/setters to the original implementation. All we will add is some instrumentation to measure the time it took to execute something. We will also associate a GUID with every new DbConnection made. Here is an example of how the 'forwarding' or proxy mechanism works:

This is how the constructor of ProxyDbConnection looks like:

public class ProxyDbConnection : DbConnection
{
    public DbProviderFactory ProxiedFactory { get; private set; }
    public DbConnection ProxiedConnection { get; private set; }
    public string Guid { get; private set; }

    public ProxyDbConnection(DbConnection proxiedConnection, 
           DbProviderFactory proxiedFactory)
    {
        ProxiedConnection = proxiedConnection;
        ProxiedFactory = proxiedFactory;
        Guid = System.Guid.NewGuid().ToString();
    } 
    ...
}

For a property:

public override ConnectionState State
{
    get { return ProxiedConnection.State; }
}

For a method:

public override void Open()
{
    ProxiedConnection.Open();
}

Below you can see a Class Diagram of these proxy classes:

Initial Profiling 'library'

I created an interface which has three methods to be implemented: IProfilerOutput.

The purpose of this interface is to allow different media to output our profiling statistics to. The first implementation of this interface will direct all profile information to the Output toolwindow of Visual Studio. This is very simply done by using Debug.Write(Line) methods. Before I go on, I should note that I already created the WCF contract that will be needed to propagate profiling info over WCF services. I used these DataContracts in the OutputWindow implementation to use the ToString() method.

For your information, this is the class diagram of the WCF Data Contracts:

This is the full implementation of the DebugProfileOutput class:

public class DebugProfileOutput: IProfileOutput
{
    #region Implementation of IProfileOutput
    public void CommandExecute(ProxyDbCommand command, TimeSpan duration, 
           ExecuteMethod method, List<QueryExecutionPlan> executionPlan, 
           object result)
    {
        var commandMessage = new Van.Parys.Data.Common.CommandMessage(
            command.CommandText, duration, method.ToString(), 
            command.ProxyDbConnection.Guid) 
              {QueryExecutionPlans = executionPlan, NonReaderResult = result};
        Debug.WriteLine(commandMessage.ToString());
    }
    public void ContextAttached(string contextName)
    {
        Debug.WriteLine(string.Format("{0} Attached!", contextName));
    }
    public void ConnectionChanged(ProxyDbConnection connection)
    {
        var connectionMessage = new ConnectionMessage() {
            ConnectionGUID = connection.Guid, 
            Open = connection.State == ConnectionState.Open};
        Debug.WriteLine(connectionMessage.ToString());
    }
    #endregion
}

To measure the time a certain action took, I used the following very handy utility method:

public static class ProfilerStopwatchAction
{
    public static TimeSpan Measure(Action action)
    {
        var startNew = Stopwatch.StartNew();
        //perform action to measure time
        action();
        startNew.Stop();
        return TimeSpan.FromMilliseconds(startNew.ElapsedMilliseconds);
    }
}

Usage:

... 
TimeSpan duration = ProfilerStopwatchAction.Measure(() => 1 + 1);
... 

Setup & Configuration of Profiling Session

Remember the initial code it took to initialize our profiling library? Guess not, eh! Well, it looked like this:

/// <summary>
/// The main entry point for the application.
/// </summary>
[STAThread]
static void Main()
{
    //First and only entry point of the profiler
    ProxyGenerator.Init();
            
    Application.Run(new Form1());  
}

Well things are about to get double as complex! That's because I added an optional parameter to the Init() function:

public static void Init(ProfilingOptions options = null) 

ProfilingOptions is a class where the following options are defined:

• bool IncludeQueryStatistics
  • This gives us the possibility to include the query execution plan in the profiling output. We all know the graphical output we get in SQL Management studio, well this is the textual representation.
  • Please note: This will not work with all SQL providers! This feature uses the 'SET SHOWPLAN_ALL ON' command, which is not valid on e.g. SqlCe!
• bool ProfileConnections
  • Indicates wether or not we are interested in profiling connection state's (Open/Close)
• ProfilingOutput ProfilingOutput
  • ProfilingOutput is an Enum which tells us which implementation of IProfileOutput to use. For the moment, the only option here is 'Debug':
  C#

  public enum ProfilingOutput
  {
      Debug
  } 

So now, we have a little more control over what is profiled, and what not. Interesting in those options is the ability to include query execution plan. The retrieval of this plan is achieved by the following code:

...
private const string SetShowplanAllOn = "SET SHOWPLAN_ALL ON";
private const string SetShowplanAllOff = "SET SHOWPLAN_ALL OFF";
...
public override object ExecuteScalar()
{
    var executionPlan = ProfileQueryExecutionPlan();

    object executeScalar = null;
    var timeSpan = ProfilerStopwatchAction.Measure(() => 
		executeScalar = ProxiedCommand.ExecuteScalar());
    EFProfiler.CommandExecute(this, timeSpan, ExecuteMethod.ExecuteScalar, 
                              executionPlan, executeScalar);
    return executeScalar;
}
...
internal List<QueryExecutionPlan> ProfileQueryExecutionPlan()
{
    if (!ProxyGenerator.Options.IncludeQueryStatistics) 
        return null;

    var executionPlan = new List<QueryExecutionPlan>();
    if (!profilingQuery)
    {
        profilingQuery = true;
        var cmd = ProxyDbConnection.CreateCommand() as ProxyDbCommand;
        cmd.Connection = this.ProxyDbConnection;
        cmd.CommandText = SetShowplanAllOn;
        cmd.CommandType = CommandType.Text;
        cmd.ProxiedCommand.ExecuteNonQuery();
        cmd.CommandText = this.CommandText;
        cmd.CommandType = CommandType.Text;
        var statsReader = cmd.ProxiedCommand.ExecuteReader();
        while (statsReader.Read())
        {
            executionPlan.Add(ParseReader(statsReader));
        }
        statsReader.Close();
        cmd.CommandText = SetShowplanAllOff;
        cmd.CommandType = CommandType.Text;
        cmd.ProxiedCommand.ExecuteNonQuery();
        profilingQuery = false;
    }
    return executionPlan;
}

A pitfall in this particular scenario was to avoid an endless loop when the IncludeQueryStatistics was set to true. This endless loop would occur because the ProfileQueryExecutionPlan method itself executes three queries. So we had to avoid that those three queries were not profiled too. This was achieved by the bool profilingQuery, as you can see in the above example.

Profiling ProxyDbCommand

Finally, we can start profiling some stuff! A demo app is included in the source files. This is the test code:

static void Main(string[] args)
{
    //single point of 'intrusion'
    ProxyGenerator.Init(new ProfilingOptions() {IncludeQueryStatistics = true, 
                        ProfilingOutput = ProfilingOutput.Debug});

    Debug.WriteLine("Test Count method");
    var count = new DemoDataEntities().Person.Count();

    Debug.WriteLine("Test Where Take(1)");
    var queryable = new DemoDataEntities().Person.Where(
        x => x.Name.StartsWith("P")).Take(1).ToList();
}

This is a snapshot of the output window:

Test Count method
a5454996-dd65-4537-97c6-55a0be329837 changed to Open
ExecuteDbDataReader: [1ms] [result:'-1'] : 
SELECT 
[GroupBy1].[A1] AS [C1]
FROM ( SELECT 
       COUNT(1) AS [A1]
       FROM [Person] AS [Extent1]
) AS [GroupBy1]
a5454996-dd65-4537-97c6-55a0be329837 changed to Closed

Test Where Take(1)
5247999a-7d94-43fb-82bd-7e0765244405 changed to Open
ExecuteDbDataReader: [0ms] [result:'-1'] : 
SELECT TOP (1) 
[Extent1].[Id] AS [Id], 
[Extent1].[Name] AS [Name], 
[Extent1].[Function] AS [Function], 
[Extent1].[Description] AS [Description]
FROM [Person] AS [Extent1]
WHERE (CHARINDEX(N'P', [Extent1].[Name])) = 1
5247999a-7d94-43fb-82bd-7e0765244405 changed to Closed

Conclusion

In this article, we added some real profiling information to our library. Please feel free to try this in your own EF project, etc. In the next article, I will explore how we can expose the profiler to the outside world using a WCF service.

Next Up

The next article will cover creating a WCF client / server setup to enable external listeners to process profiling information.