Build Your Own SQL Express Query Tracer Visual Studio Add-in

SQL Server Express is free and ideal for development purposes. When a developer exclusively uses the SQL instance, there is tighter control over the queries executed and there is no real need for a tool to trace the queries. This is typically the case, when the developer hand codes the queries. However, the situation is different when an ORM like Entity Framework is used. There are times when a developer has to understand the queries generated by the EF. Regular SQL Server comes with a profiler but unfortunately SQL Express lacks the same. It is a problem but can be easily solved.

  1. ToString() on IQueryable, for example, context.Customers.Where(x => x.Id == 5).ToString() will produce the SELECT query. This is simple and probably too simple. Queries executed by EF for lazy loading and other actions such as inserts, updates and deletes cannot be viewed using this approach.
  2. IntelliTrace, available with Visual Studio 2010 Ultimate does capture all these SQLs. But IntelliTrace is available only with Ultimate edition. Not everyone get to use the Ultimate edition. Besides, IntelliTrace does not capture parameter values.
  3. A third-party tool like DataWizard SQL Performance Profiler. This is free and there are commercial ones like Entity Framework Profiler. Not all enterprises freely allow usage of third-party tools, both free and paid ones. In most places, there will be a lot of red tape to cut.

There is one more easier option and it involves starting up SQL Express service with a couple of switches and looking at the error log file. net start MSSQL$SQLEXPRESS /T4032 /T3605 will make SQL Express log the queries in the error log, which is typically located in “C:\Program Files\Microsoft SQL Server\MSSQL10.SQLEXPRESS\MSSQL\Log\ERRORLOG”. Obviously, to use this, user must have rights to start and stop SQL Express service and read only access to the error log, which is no big deal in most of the enterprises.

Now, building on this, it is possible to quickly create a Visual Studio Add-in that displays the SQL statements in a window within Visual Studio. Of course, Add-in just automates the above steps and hence Visual Studio must be launched as an administrator for the add-in to start and stop SQL Express service. Add-in is very easy to create. A new project of type Visual Studio Add-in (under Extensibility) can be created and the wizard that gets launched following this does every thing.

Visual Studio Add-in Project

The wizard creates a Connect.cs which we will use to add our code. OnConnection() and OnDisconnection() are the two methods we are interested in. OnConnection(), called when the add-in loads, creates a new new tool window based on ProfilerUI user control and sets the visibility to true. It then stops SQL Express service and re-starts passing the required switches. In OnDisconnection(), it is the reverse. Service is stopped and re-started with no switches so that tracing is disabled.

public void OnConnection(object application, ext_ConnectMode connectMode,
                                      object addInInst, ref Array custom)
{
    _applicationObject = (DTE2)application;
    _addInInstance = (AddIn)addInInst;

    // Our code starts here
    Windows2 window = (Windows2)_applicationObject.Windows;
    object userControl = null;

    Window toolWindow = window.CreateToolWindow2(
        _addInInstance,
        Assembly.GetExecutingAssembly().Location,
        "<your namespace>.ProfilerUI",
        "SQL Express Tracer",
        "{" + Guid.NewGuid().ToString() + "}",
        ref userControl);
    toolWindow.Visible = true;

    SQLService.StartWithTraceOn();
}

public void OnDisconnection(ext_DisconnectMode disconnectMode,
                                            ref Array custom)
{
    SQLService.StartWithTraceOff();
}

ProilerUI is a UserControl that be added to the add-in project. It contains a multi-line TextBox for displaying SQL statements to users and a timer, which fires every 5 seconds.

public partial class ProfilerUI : UserControl
{
    private LogReader reader = null;

    public ProfilerUI()
    {
        InitializeComponent();

        reader = new LogReader();
        this.txtOutput.Text = "Initializing...";

        this.tmrPoller.Interval = 5000;
        this.tmrPoller.Enabled = true;
    }

    private void tmrPoller_Tick(object sender, EventArgs e)
    {
        bool mustScroll = false;
        reader.GetSQLStatements().ToList().ForEach(line =>
        {
            txtOutput.Text += (line + Environment.NewLine);
            if (!mustScroll) mustScroll = true;
        });

        if (mustScroll)
        {
            this.txtOutput.SelectionStart = this.txtOutput.Text.Length;
            this.txtOutput.ScrollToCaret();
        }
    }
}

There are two infrastructure classes – SQLService and LogReader. SQLService is fairly self-explanatory and is for managing starts and stops of MSSQL$SQLEXPRESS.

class SQLService
{
    const string SERVICE_NAME = "MSSQL$SQLEXPRESS";

    public static void StartWithTraceOn()
    {
        Start(new[] { "/T4032", "/T3605" });
    }

    public static void StartWithTraceOff()
    {
        Start();
    }

    private static void Start(string[] switches = null)
    {
        ServiceController service = GetStoppedService();

        if (switches == null)
            service.Start();
        else
            service.Start(switches);

        service.WaitForStatus(ServiceControllerStatus.Running);
    }

    private static ServiceController GetStoppedService()
    {
        ServiceController service = new ServiceController(SERVICE_NAME);

        service.Stop();
        service.WaitForStatus(ServiceControllerStatus.Stopped);

        return service;
    }
}

LogReader reads the ERRORLOG file and returns the lines that do not contain the magical string of “ODS Event:”. This is to filter out some noise and keep the focus on SQL statements. Also, this class keeps track of the lines read so that subsequent read starts off from the next line. This is only a little performance improvement since it reads the lines anyways though it skips the old lines and starts processing from where it left last time. Stream.Seek() would be a better option though.

class LogReader
{
    const string PATH = @"<Your path>\Log\ERRORLOG";
    private int numberOfLinesRead = 0;

    internal IEnumerable<string> GetSQLStatements()
    {
        StringBuilder builder = new StringBuilder();

        using (var stream = File.Open(PATH, FileMode.Open, FileAccess.Read,
                                                      FileShare.ReadWrite))
        {
            using (var reader = new StreamReader(stream))
            {
                var lines = reader.ReadToEnd()
                                     .Split(new[] { Environment.NewLine },
                                                 StringSplitOptions.None);

                if (lines.Length > numberOfLinesRead)
                {
                    var freshLines = lines.Skip(numberOfLinesRead)
                                  .Where(l => !l.Contains("ODS Event:"));

                    numberOfLinesRead = lines.Length;
                    return freshLines;
                }

                return Enumerable.Empty<string>();
            }
        }
    }
}

Add-in pounds the error log every 5 seconds. This logic can be modified to be based on events raised when the file gets changed. At least, a logic lighter than reading the lines and comparing the line count every 5 seconds would be better but that is left to the readers 🙂

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s