次の方法で共有


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)"

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