How to examine memory dump for SqlCommand.CommandText using WinDbg and SOS
Ok, so yesterday I had a post on how to generate a dump for a SqlException.
In that scenario we had an application that was throwing an exception like so:
Unhandled Exception: System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(String methodName, Boolean async)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
What we would like to know now is of course what SqlCommand is not returning in time and thereby causing this exception.
There may be easier ways to figure out what the SqlCommand is, but say for example that this is a deployed application (no source) and no access to SQL Server (no SQL Profiler), then this may be helpful.
This post is not intended to go into depth on how to debug .Net/ADO.Net applications, for this I would recommend my colleagues Tess blog.
So, first follow the steps from last post in order to create the application and dump. Found here
Once this is done, you should have some .dmp files in the “C:\Dumps” directory.
Now, the object of this is to figure out what SQL was executing when the application timed out. This can be done like so:
Download and install the debugging tools from here:
"Debugging Tools for Windows - Overview"
https://www.microsoft.com/whdc/devtools/debugging/default.mspx
Start the debugger (WinDbg) and go File – Open Crash Dump, select the .dmp file you are interested in (should have ‘First Chance’ in the filename)
Then you need to load what is called the symbols, so go File -> Symbol File Path, set this to:
srv*C:\Symbols*https://msdl.microsoft.com/download/symbols
Then you need to load the SOS extension. This file is found in the .Net framework directory, depending on what type of machine (x86/x64) you are running.
C:\Windows\Microsoft.NET\Framework\v2.0.50727\sos.dll
C:\Windows\Microsoft.NET\Framework64\v2.0.50727\sos.dll
So, in windbg, in order to load the SOS extension, type the following and hit enter:
.load C:\WINDOWS\Microsoft.NET\Framework64\v2.0.50727\sos.dll
On this is done, let us check what the CLR stack looks like at the time of the exception. Do this by running:
!clrstack
This should give an output like this:
0:000> !clrstack
OS Thread Id: 0x2d0 (0)
*** WARNING: Unable to verify checksum for System.Data.ni.dll
Child-SP RetAddr Call Site
000000000012ec90 00000642b78c50b5 System.Data.SqlClient.SqlConnection.OnError(System.Data.SqlClient.SqlException, Boolean)
000000000012ecd0 00000642b78c13fb System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(System.Data.SqlClient.TdsParserStateObject)
000000000012ed30 00000642b789a712 System.Data.SqlClient.TdsParser.Run(System.Data.SqlClient.RunBehavior, System.Data.SqlClient.SqlCommand, System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.BulkCopySimpleResultSet, System.Data.SqlClient.TdsParserStateObject)
000000000012ee00 00000642b7898096 System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(System.String, Boolean)
000000000012ee90 00000642b7897756 System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(System.Data.Common.DbAsyncResult, System.String, Boolean)
000000000012ef40 00000642801b0248 System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
000000000012efb0 000006427f602672 TimeOutApp.Program.Main(System.String[])
This seems correct, there is an error on a SqlConnection, it all started with a call to a SqlCommand.ExecuteNonQuery.
So, let us have a look at the objects on the stack. Do this by running:
!dumpstackobjects
This should give an output like this:
0:000> !dumpstackobjects
OS Thread Id: 0x2d0 (0)
RSP/REG Object Name
000000000012e9b8 000000000207ab80 System.String
000000000012eab0 000000000205bdd0 System.Data.SqlClient.TdsParserStateObject
000000000012eab8 000000000205bb30 System.Data.SqlClient.TdsParser
000000000012eac0 000000000206ff70 System.Data.SqlClient.SqlCommand
000000000012eac8 000000000207aa50 System.Data.SqlClient.SqlException
000000000012ead0 000000000207aa50 System.Data.SqlClient.SqlException
000000000012eae0 000000000207aa50 System.Data.SqlClient.SqlException
000000000012eb00 000000000207aa50 System.Data.SqlClient.SqlException
000000000012ebd0 000000000207aa50 System.Data.SqlClient.SqlException
000000000012ebd8 000000000207aa50 System.Data.SqlClient.SqlException
000000000012ebf0 000000000206ff70 System.Data.SqlClient.SqlCommand
000000000012ebf8 000000000205bb30 System.Data.SqlClient.TdsParser
000000000012ec00 000000000205bdd0 System.Data.SqlClient.TdsParserStateObject
000000000012ec10 000000000205bb30 System.Data.SqlClient.TdsParser
000000000012ec70 0000000001ff5640 System.Data.SqlClient.SqlConnection
000000000012ec78 0000000001ff5640 System.Data.SqlClient.SqlConnection
000000000012eca0 000000000206ff70 System.Data.SqlClient.SqlCommand
000000000012eca8 000000000205bb30 System.Data.SqlClient.TdsParser
000000000012ecb0 000000000205bb30 System.Data.SqlClient.TdsParser
.. truncated ..
So this also seems promising, we have a SqlException and a SqlCommand, let’s check the SqlException first and see what the error message is.
This is done by passing the objects address to the !dumpobject method.
0:000> !dumpobj 000000000207aa50
Name: System.Data.SqlClient.SqlException
MethodTable: 00000642b7a2e978
EEClass: 00000642b73c5aa8
Size: 144(0x90) bytes
(C:\WINDOWS\assembly\GAC_64\System.Data\2.0.0.0__b77a5c561934e089\System.Data.dll)
Fields:
MT Field Offset Type VT Attr Value Name
00000642784365e8 40000b5 8 System.String 0 instance 0000000000000000 _className
0000064278434990 40000b6 10 ...ection.MethodBase 0 instance 0000000000000000 _exceptionMethod
00000642784365e8 40000b7 18 System.String 0 instance 0000000000000000 _exceptionMethodString
00000642784365e8 40000b8 20 System.String 0 instance 000000000207a950 _message
000006427842dc08 40000b9 28 ...tions.IDictionary 0 instance 000000000207aae0 _data
00000642784368b0 40000ba 30 System.Exception 0 instance 0000000000000000 _innerException
00000642784365e8 40000bb 38 System.String 0 instance 0000000000000000 _helpURL
0000064278435ed8 40000bc 40 System.Object 0 instance 0000000000000000 _stackTrace
00000642784365e8 40000bd 48 System.String 0 instance 0000000000000000 _stackTraceString
.. truncated ..
It makes sense that the message is in the _message variable, so let’s check the value of that, again using !dumpobject and the address.
0:000> !dumpobj 000000000207a950
Name: System.String
MethodTable: 00000642784365e8
EEClass: 000006427803e4f0
Size: 254(0xfe) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
Fields:
MT Field Offset Type VT Attr Value Name
000006427843d858 4000096 8 System.Int32 1 instance 115 m_arrayLength
000006427843d858 4000097 c System.Int32 1 instance 114 m_stringLength
0000064278438030 4000098 10 System.Char 1 instance 54 m_firstChar
.. truncated ..
So this is clearly the same error that we got from the application, promising. Let’s then examine the SqlCommand that we got by running !dumpstackobjects earlier.
Again, this is done by passing the SqlCommand object address to the !dumpobj method.
0:000> !dumpobj 000000000206ff70
Name: System.Data.SqlClient.SqlCommand
MethodTable: 00000642b7a2f240
EEClass: 00000642b73c5fe8
Size: 224(0xe0) bytes
(C:\WINDOWS\assembly\GAC_64\System.Data\2.0.0.0__b77a5c561934e089\System.Data.dll)
Fields:
MT Field Offset Type VT Attr Value Name
0000064278435ed8 400018a 8 System.Object 0 instance 0000000000000000 __identity
0000064274b3d5b0 40008c3 10 ...ponentModel.ISite 0 instance 0000000000000000 site
0000064274b6cec8 40008c4 18 ....EventHandlerList 0 instance 0000000000000000 events
0000064278435ed8 40008c2 210 System.Object 0 static 0000000001ff9120 EventDisposed
000006427843d858 40016f2 b0 System.Int32 1 instance 1 ObjectID
00000642784365e8 40016f3 20 System.String 0 instance 0000000001ff3e90 _commandText
00000642b79ee2c0 40016f4 b4 System.Int32 1 instance 0 _commandType
000006427843d858 40016f5 b8 System.Int32 1 instance 10 _commandTimeout
00000642b79f0ab0 40016f6 bc System.Int32 1 instance 3 _updatedRowSource
00000642784357b8 40016f7 d0 System.Boolean 1 instance 0 _designTimeInvisible
00000642b7a31e90 40016f8 28 ...ent.SqlDependency 0 instance 0000000000000000 _sqlDep
00000642784357b8 40016f9 d1 System.Boolean 1 instance 0 _inPrepare
000006427843d858 40016fa c0 System.Int32 1 instance -1 _prepareHandle
00000642784357b8 40016fb d2 System.Boolean 1 instance 0 _hiddenPrepare
00000642b7a2fbe0 40016fc 30 ...rameterCollection 0 instance 0000000000000000 _parameters
.. truncated ..
So now naturally we’ll just dump out the value for the commandText variable:
0:000> !dumpobj 0000000001ff3e90
Name: System.String
MethodTable: 00000642784365e8
EEClass: 000006427803e4f0
Size: 76(0x4c) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: waitfor delay '00:00:20' ;
Fields:
MT Field Offset Type VT Attr Value Name
000006427843d858 4000096 8 System.Int32 1 instance 26 m_arrayLength
000006427843d858 4000097 c System.Int32 1 instance 25 m_stringLength
0000064278438030 4000098 10 System.Char 1 instance 77 m_firstChar
.. truncated ..
This gives us the command that was executing when the application was throwing the exception.
In this case we have forcefully made the command to wait for 20 seconds. In your scenario you should take what you found here and
try to execute it from outside the application, for example from SQL Server Management Studio. If it runs slowly from there, we can rule out the client side as the cause of the error.
But as mentioned, this was just a very short introduction on how to find out what SqlCommand.CommandText was executing when getting a timeout.
For more info on SOS, have a look here:
".NET Framework Tools - SOS Debugging Extension (SOS.dll)"