Read last executed SQL statement from a memory dump

In this post I’m going to show you how to diagnose SQL exceptions using memory dumps. Imagine you have a web application deployed on a production server. Your application is using Elmah configured to log all exceptions to a dedicated table. One day you receive information that users are unable to make orders and in the Elmah log there are lots of SqlTypeExceptions:

SqlDateTime overflow. Must be between 1/1/1753 12:00:00 AM and 12/31/9999 11:59:59 PM.
 at System.Data.SqlClient.TdsParser.TdsExecuteRPC(_SqlRPC[] rpcArray, Int32 timeout, Boolean inSchema, SqlNotificationRequest notificationRequest, TdsParserStateObject stateObj, Boolean isCommandProc, Boolean sync, TaskCompletionSource`1 completion, Int32 startRpc, Int32 startParam)
 at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite)
 at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
...

No more information available. If you are using NHibernate you may turn on SQL logging but, if you have thousands of users, this will have a negative impact on the application responsiveness. Another idea might be to use ADO.NET ETW logs – even though this way we will minimize the performance drop, it’s still not a perfect solution. ETW logs weigh hundreds of MB and contain a tremendous amount of information, which you need to filter and analyze. I plan to write about this type of logging in the future. For now, let’s take a third approach: create a production memory dump when the application breaks and analyze it locally in the debugger.

Create a production memory dump

Some time ago I wrote a post about using Adplus in a managed applications diagnostics where I configured Adplus to make a memory dump only when specific managed exception is thrown. Today we will adapt the configuration file from that post to our case. To test it I created a very simple web application that tries to place an order in the Orders table. Please download its sourcecode from http://lowleveldesign.codeplex.com/releases/view/89634. To create a sample orders database run the orders.sql script included in the package. Next run the application on any valid web server – I chose IISExpress but you may also use IIS or Cassini:

> "c:\Program Files (x86)\IIS Express\iisexpress.exe" /path:"%cd%"

Copied template config file 'c:\Program Files (x86)\IIS Express\AppServer\applicationhost.config' to 'C:\Users\SEBAST~1\
AppData\Local\Temp\iisexpress\applicationhost201261553510667.config'
Updated configuration file 'C:\Users\SEBAST~1\AppData\Local\Temp\iisexpress\applicationhost201261553510667.config' with
given cmd line info.
Starting IIS Express ...
Successfully registered URL "http://localhost:8080/" for site "Development Web Site" application "/"
Registration completed
IIS Express is running.
Enter 'Q' to stop IIS Express

When you try to open http://localhost:8080 you should see a yellow screen of death with information about the SqlTypeException. Now we want to have a dump at the very first moment when the exception occurs. The Adplus configuration file that we will use looks as follows:

<adplus version="2">
  <keywords>
    <!-- 
    If you are attaching to the process just use: .loadby sos clr.
    
    If it's .net 2.0 you need to use: .loadby sos mscorwks
    or only .loadby sos mscorwks if you are attaching to the process
     -->
    <keyword name="LoadSOS">.loadby sos clr</keyword>
    <keyword name="PrintManagedException">!PrintException</keyword>
    <keyword name="ManagedStack">!CLRStack -a</keyword>
    <keyword name="FullDumpOnSqlTypeException">!soe System.Data.SqlTypes.SqlTypeException 1;.if(@$t1==1) {.dump /ma /u ${AdpDumpDir}\FULLDUMP_SqlTypeException_${AdpProcName}_.dmp}</keyword>
  </keywords>
  <settings>
    <runmode>crash</runmode>
    <lastscriptcommand>qd</lastscriptcommand>
  </settings>
  <postcommands>
    <debugactions>LoadSOS</debugactions>
  </postcommands>
  <exceptions>
    <allexceptions>
      <actions1>LOG</actions1>
      <returnaction1>GN</returnaction1>
      <actions2>LOG</actions2>
      <returnaction2>GN</returnaction2>
    </allexceptions>
    <allevents>
      <actions1>LOG</actions1>
      <returnaction1>GN</returnaction1>
      <actions2>LOG</actions2>
      <returnaction2>GN</returnaction2>
    </allevents>
    <exception code="clr">
      <actions1>
        PrintManagedException;
        ManagedStack;
        FullDumpOnSqlTypeException
      </actions1>
      <returnaction1>GN</returnaction1>
      <actions2>Log;</actions2>
      <returnaction2>GN</returnaction2>
    </exception>
  </exceptions>
</adplus>

If you don’t have Adplus installed on your machine, download and install Debugging Tools for Windows. Now we need to find the PID of the process. For IISExpress it’s easy – just find a process named iisexpress.exe in the task manager. For production IIS you will need to find the correct instance of the w3wp.exe – there are plenty of sites that describe how to do that so just google them:) Finally we are ready to run the adplus command (5280 is a PID of my IISExpress instance):

adplus.exe -c log-exceptions.adplus.config -o c:\dumps -p 5280

Refresh the website and after a moment there should be a new subfolder created in the c:\dumps folder. There you will find three text files and four memory dumps. The number of dumps is greater than one because a dump is created not only when the first SqlTypeException is thrown but also on any rethrow action. You can now safely detach Adplus console (Ctrl+Break and then qd command) and copy the first dump file to a machine which has Visual Studio installed.

Analyze the memory dump in Visual Studio

After you open a dump file in Visual Studio (File -> Open File…) you will be presented with the following screen:

For a managed dump choose Debug with mixed option and be amazed how Visual Studio opens a debugger, loads modules and sets up all the debugger windows. For the best debugging experience make sure you have a valid symbol path configured (either through _NT_SYMBOL_PATH variable or using Tools -> Options -> Debugging -> Symbols) and “Enable just my code” option in the debugger settings is unchecked. After a moment you should be presented with an “Exception occured” dialog:

After you press break you can find yourself at the exact moment when the exception occurred. As we are looking for the last executed SQL statement we need to find on the stack a frame that holds a reference to an active SqlCommand instance. Let’s choose a stack frame preseneted on a picture below and double click it:

We can see in the “Autos” window that this points to a SqlCommand instance. To return a SQL command you can either expand this in any of the watch windows or type this.CommandText in the Immediate window:

this.CommandText
"insert into Orders (Username, Product, Cash, ActivityId, CreatedOn, Status, StatusMessage) values (@Username, @Product, @Cash, @ActivityId, @CreatedOn, @Status, @StatusMessage)"

Having found the query we need to retrieve its parameters’ values. Fortunately it’s really easy as SqlCommand keeps its parameters in a _parameters private variable of type SqlParameterCollection. Inner variable of the SqlParameterCollection called _items is a raw array of parameters which renders in the Immediate window as follows:

this._parameters._items
Count = 7
    [0]: {ActivityId}
    [1]: {Cash}
    [2]: {CreatedOn}
    [3]: {Product}
    [4]: {Status}
    [5]: {StatusMessage}
    [6]: {Username}

As we can see from the output the default visualizer shows just names of the parameters. In order to retrieve their values we need to expand each of them and check its Value property. Fortunately we can do better using one of the Visual Studio customizations. In folder C:\Users\<your login>\Documents\<your Visual Studio version>\Visualizers there is a special file named autoexp.cs which stores your local visualizer settings (defined using DebuggerDisplayAttribute). If you can’t find this file you can safely copy it from <Visual Studio installation folder>\Common7\Packages\Debugger\Visualizers\Original\. We can then append a new rule by the end of this file:

[assembly: DebuggerDisplay(@"Name = {_parameterName}, Value = {_value}", Target = typeof(System.Data.SqlClient.SqlParameter))]

Finally we need to recompile it:

csc /t:library autoexp.cs

and restart Visual Studio. Next time we repeat all the steps described above and after issuing this._parameters._items we should see:

Count = 7
    [0]: Name = "ActivityId", Value = {00000000-0000-0000-0000-000000000000}
    [1]: Name = "Cash", Value = 12
    [2]: Name = "CreatedOn", Value = {0001-01-01 00:00:00}
    [3]: Name = "Product", Value = "testprod"
    [4]: Name = "Status", Value = {}
    [5]: Name = "StatusMessage", Value = {}
    [6]: Name = "Username", Value = "test"

From this output we can easily find the faulting variable (CreatedOn) and its invalid value (0001-01-01 00:00:00).

As usual all the source codes are available for download on my blog samples page. I hope that this post will help you in diagnosing SQL exceptions in the future. If you have any other ideas how we can read the last executed statement please share them in comments.