In this post, I’m going to show you one way of diagnosing SQL exceptions by 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 – although 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 an 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 source code 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 as well 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 are going to use looks as follows:
<adplus version="2">
<keywords>
<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. In production environment, you will need to find the correct instance of the w3wp.exe – there are plenty of sites that describe how to that. 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 admire how Visual Studio opens a debugger, loads modules and sets up all the debugger windows. For the best debugging experience, make sure that 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 occurred” dialog:
After you press break, you can find yourself at an 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 a 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 the comments.