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”


http://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*http://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)”


http://msdn.microsoft.com/en-us/library/bb190764.aspx


 


Comments (0)