Troubleshooting SQL Server Management Studio with SQL Profiler and Debugging Tools – Part 3

Artikel
02/03/2010

(An alternate title for this post could be “How to debug SSMS managed code”)

In the first 2 posts of this topic we used SQL Profiler and some common sense to diagnose a problem within SSMS. Then we used DebugDiag to collect a memory dump when a specific exception was thrown. Now in the 3rd part we’ll analyze that dump used windbg and public symbols from the Microsoft symbols server.

This post assumes a certain familiarity with managed debugging using windbg. If you need some background on this topic, a good place to start is by reading the blog of Tess.

To understand the context of this debugging, you should really read the first 2 posts in the series, but as a brief reminder, we collect a dump of the SSMS process (ssms.exe in SQL 2008 and sqlwb.exe in SQL 2005) when a specific condition occurs – in this case an exception thrown when trying to view SQL Agent job history. The dump below is from a sqlwb.exe 2005 client, but the theory is identical. The main point which this post demonstrates is that unlike when debugging the database engine process of SQL Server (sqlservr.exe), using purely public symbols , interesting information can be gleaned from the dump because most of the interesting structures are in managed code which can be interpretted with the windbg extension sos.dll.

My base setup for this debugging:

A blank hyper-V machine running Windows 7 Ultimate, connected to the internet

A default installation of debugging tools for windows downloaded from here:

https://www.microsoft.com/whdc/devtools/debugging/installx86.Mspx

A symbol path set exactly as per the example “getting started” page here:

https://www.microsoft.com/whdc/devtools/debugging/debugstart.mspx

i.e. the symbol path used is:

SRV*c:\websymbols*https://msdl.microsoft.com/download/symbols

So here’s the debugging output with notes:

* First off we load the public sos.dll so we can do managed debugging

0:018> .load c:\windows\microsoft.net\framework\v2.0.50727\sos.dll

* We’ve opened directly to the thread where the exception occurred

* let’s look at the CLRSTACK

0:018> !clrstack

OS Thread Id: 0x6ac (18)

ESP EIP

0822ef3c 77e4bef7 [HelperMethodFrame: 0822ef3c]

0822efe0 799d766a System.DateTime.TimeToTicks(Int32, Int32, Int32)

0822eff0 2ec8e92c Microsoft.SqlServer.Management.Smo.PostProcessCreateDateTime.GetDateTime(System.Object, System.Object)

0822f010 2ec91584 Microsoft.SqlServer.Management.Smo.PostProcessJobActivity.GetColumnData(System.String, System.Object, Microsoft.SqlServer.Management.Smo.DataProvider)

0822f064 2ec86ced Microsoft.SqlServer.Management.Smo.DataProvider.ManipulateRowDataPostProcess()

0822f07c 2ec872b9 Microsoft.SqlServer.Management.Smo.DataProvider.GetTable()

0822f08c 2ec84436 Microsoft.SqlServer.Management.Smo.ExecuteSql.ExecuteWithResults(System.Collections.Specialized.StringCollection, System.Object, Microsoft.SqlServer.Management.Smo.StatementBuilder)

0822f098 2ec804db Microsoft.SqlServer.Management.Smo.SqlObjectBase.FillData(Microsoft.SqlServer.Management.Smo.ResultType, System.Collections.Specialized.StringCollection, System.Object, Microsoft.SqlServer.Management.Smo.StatementBuilder)

0822f0b8 2ec803c4 Microsoft.SqlServer.Management.Smo.SqlObjectBase.FillDataWithUseFailure(Microsoft.SqlServer.Management.Smo.SqlEnumResult, Microsoft.SqlServer.Management.Smo.ResultType)

0822f0f8 2ec80339 Microsoft.SqlServer.Management.Smo.SqlObjectBase.BuildResult(Microsoft.SqlServer.Management.Smo.EnumResult)

0822f138 2ec7fea3 Microsoft.SqlServer.Management.Smo.SqlObjectBase.GetData(Microsoft.SqlServer.Management.Smo.EnumResult)

0822f148 2eb5daf8 Microsoft.SqlServer.Management.Smo.Environment.GetData()

0822f178 2eb5da5c Microsoft.SqlServer.Management.Smo.Environment.GetData(Microsoft.SqlServer.Management.Smo.Request, System.Object)

0822f18c 2eb5caef Microsoft.SqlServer.Management.Smo.Enumerator.GetData(System.Object, Microsoft.SqlServer.Management.Smo.Request)

0822f1b0 2eb5ccd6 Microsoft.SqlServer.Management.Smo.Enumerator.Process(System.Object, Microsoft.SqlServer.Management.Smo.Request)

0822f1e4 30983b38 Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher.FetchJobs(System.String)

0822f200 3098349a Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher.FetchJobs(Microsoft.SqlServer.Management.SqlManagerUI.JobActivityFilter)

0822f214 3098230e Microsoft.SqlServer.Management.SqlManagerUI.JobsPanel.RefreshJobs()

0822f240 3097f028 Microsoft.SqlServer.Management.SqlManagerUI.JobActivityMonitor.Microsoft.SqlServer.Management.UI.ActivityMonitor.IActivityMonitor.RefreshSnapshot()

0822f244 053f08f7 Microsoft.SqlServer.Management.UI.ActivityMonitor.ActivityMonitorUserControl.WorkerEntryPoint(System.Object)

0822f280 792c9e4f System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)

0822f288 792f5681 System.Threading.ExecutionContext.runTryCode(System.Object)

0822f6b8 79e71b4c [HelperMethodFrame_PROTECTOBJ: 0822f6b8] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)

0822f720 792f5577 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

0822f73c 792e01c5 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

0822f754 792ca3b3 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)

0822f768 792ca249 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)

0822f8f8 79e71b4c [GCFrame: 0822f8f8]

* this shows us some fairly expected output that we have a stack which indicates we are using SMO to populate some data to do with SQL Agent jobs (Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher.FetchJobs)

* let’s look at the exception to check it’s what we wanted

* it shows the details of the exception which SSMS reported (Hour, Minute, and Second parameters describe an un-representable DateTime)

0:018> !pe

Exception object: 016588b4

Exception type: System.ArgumentOutOfRangeException

Message: Hour, Minute, and Second parameters describe an un-representable DateTime.

InnerException: <none>

StackTrace (generated):

<none>

StackTraceString: <none>

HResult: 80131502

* now we want to look at what these functions were actually doing

* dump all objects on the stack to look back through recent history (most recent is at the top)

* scanning down here to look for anything of interest

* we see that we have a System.DBNull sitting next to a System.String named NextRunDate – this might be of interest

* in addition to that we can see the server connection object which will contain the details of the connection and also the actual TSQL executed

0:018> !dso

OS Thread Id: 0x6ac (18)

ESP/REG Object Name

0822eed0 016588b4 System.ArgumentOutOfRangeException

0822ef1c 016588b4 System.ArgumentOutOfRangeException

0822ef60 016588b4 System.ArgumentOutOfRangeException

0822efbc 0156b85c System.String ArgumentOutOfRange_BadHourMinuteSecond

0822efc4 016588b4 System.ArgumentOutOfRangeException

0822efe0 016588b4 System.ArgumentOutOfRangeException

0822eff8 015cd46c Microsoft.SqlServer.Management.Smo.PostProcessJobActivity

0822effc 0165889c System.Int32

0822f00c 016588a8 System.Int32

0822f010 01658880 System.Data.RBTree`1+RBTreeEnumerator[[System.Data.DataRow, System.Data]]

0822f014 01603e84 System.Data.DataRow

0822f018 015cc064 System.String NextRunDate

0822f01c 015cd46c Microsoft.SqlServer.Management.Smo.PostProcessJobActivity

0822f044 015d34f0 System.Data.DataRow

0822f048 015cd46c Microsoft.SqlServer.Management.Smo.PostProcessJobActivity

0822f04c 015cdf84 Microsoft.SqlServer.Management.Smo.DataProvider

0822f05c 015cdf84 Microsoft.SqlServer.Management.Smo.DataProvider

0822f060 011ee95c System.DBNull

0822f064 015cc064 System.String NextRunDate

0822f068 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f06c 015cdf84 Microsoft.SqlServer.Management.Smo.DataProvider

0822f094 015ccd18 Microsoft.SqlServer.Management.Smo.StatementBuilder

0822f0b0 01594dbc Microsoft.SqlServer.Management.Common.ServerConnection

0822f0c0 015cd964 System.Collections.Specialized.StringCollection

0822f0c4 015cca78 Microsoft.SqlServer.Management.Smo.SqlEnumResult

0822f0c8 015c8a00 Microsoft.SqlServer.Management.Smo.SqlObject

0822f0e0 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f124 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f148 015cc7bc System.Collections.ArrayList+ArrayListEnumeratorSimple

0822f14c 015cca78 Microsoft.SqlServer.Management.Smo.SqlEnumResult

0822f164 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f168 015c462c Microsoft.SqlServer.Management.Smo.Environment

0822f188 01594dbc Microsoft.SqlServer.Management.Common.ServerConnection

0822f194 01594dbc Microsoft.SqlServer.Management.Common.ServerConnection

0822f19c 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f1cc 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f1e0 015c4590 Microsoft.SqlServer.Management.Smo.Request

0822f1e4 0150cb08 System.String /Job

0822f1e8 011d1198 System.String

0822f1ec 0158101c Microsoft.SqlServer.Management.SqlManagerUI.JobActivityFilter

0822f1f0 01597a6c Microsoft.SqlServer.Management.SqlManagerUI.JobFetcher

0822f204 01591e78 Microsoft.SqlServer.Management.SqlManagerUI.JobsPanel

0822f214 01591e78 Microsoft.SqlServer.Management.SqlManagerUI.JobsPanel

0822f21c 01217510 System.Runtime.CompilerServices.RuntimeHelpers+CleanupCode

0822f224 014f9c50 System.Threading.ExecutionContext

0822f250 015a5174 Microsoft.SqlServer.Management.UI.ActivityMonitor.ActivityMonitorUserControl+BackgroundRefreshJobDescription

0822f254 01581054 Microsoft.SqlServer.Management.UI.ActivityMonitor.ActivityMonitorUserControl

0822f344 012174f0 System.Runtime.CompilerServices.RuntimeHelpers+TryCode

0822f410 01217510 System.Runtime.CompilerServices.RuntimeHelpers+CleanupCode

0822f4b8 012174f0 System.Runtime.CompilerServices.RuntimeHelpers+TryCode

0822f638 01217510 System.Runtime.CompilerServices.RuntimeHelpers+CleanupCode

0822f6f4 012174f0 System.Runtime.CompilerServices.RuntimeHelpers+TryCode

0822f6f8 01217510 System.Runtime.CompilerServices.RuntimeHelpers+CleanupCode

0822f6fc 015a561c System.Threading.ExecutionContext+ExecutionContextRunData

0822f724 011f4ecc System.Threading.ContextCallback

0822f72c 014f9c50 System.Threading.ExecutionContext

0822f738 015a51cc System.Threading._ThreadPoolWaitCallback

0822f750 015a51cc System.Threading._ThreadPoolWaitCallback

* dump the server connection object – this is always a useful object to be able to locate and look at, because within it you can see all manner of properties about the connection and the batch executing

0:018> !do 01594dbc

Name: Microsoft.SqlServer.Management.Common.ServerConnection

MethodTable: 2e2bda28

EEClass: 2e283d48

Size: 144(0x90) bytes

(C:\WINDOWS\assembly\GAC_MSIL\Microsoft.SqlServer.ConnectionInfo\9.0.242.0__89845dcd8080cc91\Microsoft.SqlServer.ConnectionInfo.dll)

Fields:

MT Field Offset Type VT Attr Value Name

793044cc 4000036 40 System.Boolean 1 instance 1 m_BlockUpdates

79330a00 4000037 4 System.String 0 instance 01594eac m_ServerInstance

79330a00 4000038 8 System.String 0 instance 011d1198 m_Login

7995d420 4000039 c ...rity.SecureString 0 instance 00000000 m_Password

793044cc 400003a 41 System.Boolean 1 instance 1 m_LoginSecure

79330a00 400003b 10 System.String 0 instance 011d1198 m_ConnectAsUserName

79330a00 400003c 14 System.String 0 instance 011d1198 m_ConnectAsUserPassword

793044cc 400003d 42 System.Boolean 1 instance 0 m_ConnectAsUser

793044cc 400003e 43 System.Boolean 1 instance 1 m_NonPooledConnection

79332c4c 400003f 28 System.Int32 1 instance 0 m_PooledConnectionLifetime

79332c4c 4000040 2c System.Int32 1 instance 0 m_MinPoolSize

79332c4c 4000041 30 System.Int32 1 instance 100 m_MaxPoolSize

79332c4c 4000042 34 System.Int32 1 instance 15 m_ConnectTimeout

2e2bc5b4 4000043 38 System.Int32 1 instance 8 m_NetworkProtocol

79330a00 4000044 18 System.String 0 instance 01594e4c m_ApplicationName

79330a00 4000045 1c System.String 0 instance 011d1198 m_WorkstationId

79330a00 4000046 20 System.String 0 instance 011d1198 m_DatabaseName

79332c4c 4000047 3c System.Int32 1 instance 4096 m_PacketSize

7995d420 4000048 24 ...rity.SecureString 0 instance 00000000 m_ConnectionString

793044cc 4000049 44 System.Boolean 1 instance 0 m_MultipleActiveResultSets

793044cc 400004a 45 System.Boolean 1 instance 0 shouldEncryptConnection

6523d7a0 400004b 48 ...ent.SqlConnection 0 instance 01594f10 m_SqlConnectionObject

793044cc 400004c 46 System.Boolean 1 instance 1 m_InUse

79332c4c 400004d 68 System.Int32 1 instance 0 m_LoginFailedClients

2e2bc50c 400004e 4c ...ssageEventHandler 0 instance 00000000 m_RemoteLoginFailedHandler

656629a8 400004f 50 ...ssageEventHandler 0 instance 00000000 m_SqlInfoMessageHandler

2e2bd89c 4000050 54 ...ommon.CapturedSql 0 instance 01594ee0 m_CapuredSQL

2e2bc8d4 4000051 6c System.Int32 1 instance 1 m_AutoDisconnectMode

793044cc 4000052 47 System.Boolean 1 instance 0 bIsUserConnected

2e2be0b0 4000053 58 ...mon.ServerVersion 0 instance 015c172c m_serverVersion

79332c4c 4000054 70 System.Int32 1 instance 10 lockTimeout

2e2bc50c 4000055 5c ...ssageEventHandler 0 instance 00000000 ServerMessageInternal

2e2bc480 4000056 60 ...ementEventHandler 0 instance 00000000 StatementExecuted

2e2bc50c 4000057 64 ...ssageEventHandler 0 instance 00000000 RemoteLoginFailedInternal

79332c4c 400005b 80 System.Int32 1 instance 0 m_StatementTimeout

79330a00 400005c 74 System.String 0 instance 01428dcc m_BatchSeparator

79332c4c 400005d 84 System.Int32 1 instance 0 m_TransactionDepth

2e2bc6f4 400005e 88 System.Int32 1 instance 1 m_ExecutionMode

6523db4c 400005f 78 ...Client.SqlCommand 0 instance 01594f48 m_SqlCommand

79330a00 4000060 7c System.String 0 instance 015c1a70 m_TrueName

*dump the SqlCommand object

0:018> !do 01594f48

Name: System.Data.SqlClient.SqlCommand

MethodTable: 6523db4c

EEClass: 6515c250

Size: 132(0x84) bytes

(C:\WINDOWS\assembly\GAC_32\System.Data\2.0.0.0__b77a5c561934e089\System.Data.dll)

Fields:

MT Field Offset Type VT Attr Value Name

7933061c 400018a 4 System.Object 0 instance 00000000 __identity

7a5d2a58 40008c3 8 ...ponentModel.ISite 0 instance 00000000 site

7a5ecd2c 40008c4 c ....EventHandlerList 0 instance 00000000 events

7933061c 40008c2 108 System.Object 0 static 01201278 EventDisposed

79332c4c 40016e3 58 System.Int32 1 instance 58 ObjectID

79330a00 40016e4 10 System.String 0 instance 014e3850 _commandText

6523e698 40016e5 5c System.Int32 1 instance 0 _commandType

79332c4c 40016e6 60 System.Int32 1 instance 0 _commandTimeout

6565989c 40016e7 64 System.Int32 1 instance 3 _updatedRowSource

793044cc 40016e8 78 System.Boolean 1 instance 0 _designTimeInvisible

6567ecdc 40016e9 14 ...ent.SqlDependency 0 instance 00000000 _sqlDep

793044cc 40016ea 79 System.Boolean 1 instance 0 _inPrepare

79332c4c 40016eb 68 System.Int32 1 instance -1 _prepareHandle

793044cc 40016ec 7a System.Boolean 1 instance 0 _hiddenPrepare

6523e8b4 40016ed 18 ...rameterCollection 0 instance 00000000 _parameters

6523d7a0 40016ee 1c ...ent.SqlConnection 0 instance 01594f10 _activeConnection

793044cc 40016ef 7b System.Boolean 1 instance 0 _dirty

656616a4 40016f0 6c System.Int32 1 instance 0 _execType

793041d0 40016f1 20 System.Object[] 0 instance 00000000 _rpcArrayOf1

6524233c 40016f2 24 ...t._SqlMetaDataSet 0 instance 015f9100 _cachedMetaData

65241e94 40016f3 28 ...+CachedAsyncState 0 instance 015c19fc _cachedAsyncState

79332c4c 40016f4 70 System.Int32 1 instance -1 _rowsAffected

6567d4b8 40016f5 2c ...tificationRequest 0 instance 00000000 _notification

793044cc 40016f6 7c System.Boolean 1 instance 1 _notificationAutoEnlist

6567da8c 40016f7 30 ...nt.SqlTransaction 0 instance 00000000 _transaction

65659328 40016f8 34 ...letedEventHandler 0 instance 00000000 _statementCompletedEventHandler

65241814 40016f9 38 ...ParserStateObject 0 instance 00000000 _stateObj

793044cc 40016fa 7d System.Boolean 1 instance 0 _pendingCancel

793044cc 40016fb 7e System.Boolean 1 instance 0 _batchRPCMode

00000000 40016fc 3c 0 instance 00000000 _RPCList

793041d0 40016fd 40 System.Object[] 0 instance 00000000 _SqlRPCBatchArray

00000000 40016fe 44 0 instance 00000000 _parameterCollectionList

79332c4c 40016ff 74 System.Int32 1 instance 0 _currentlyExecutingBatch

656732b0 4001700 48 ...miRequestExecutor 0 instance 00000000 _smiRequest

65672df8 4001701 4c ...Server.SmiContext 0 instance 00000000 _smiRequestContext

6567e144 4001702 50 ...+CommandEventSink 0 instance 00000000 _smiEventSink

65672f4c 4001703 54 ...DeferedProcessing 0 instance 00000000 _outParamEventSink

79332c4c 40016e2 878 System.Int32 1 static 59 _objectTypeCount

793041d0 4001704 78c System.Object[] 0 static 01427968 PreKatmaiProcParamsNames

793041d0 4001705 790 System.Object[] 0 static 014279b4 KatmaiProcParamsNames

* dump the command text

0:018> !do 014e3850

Name: System.String

MethodTable: 79330a00

EEClass: 790ed64c

Size: 68(0x44) bytes

(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String: exec msdb.dbo.sp_help_job

Fields:

MT Field Offset Type VT Attr Value Name

79332c4c 4000096 4 System.Int32 1 instance 26 m_arrayLength

79332c4c 4000097 8 System.Int32 1 instance 25 m_stringLength

793316e0 4000098 c System.Char 1 instance 65 m_firstChar

79330a00 4000099 10 System.String 0 shared static Empty

>> Domain:Value 001831e0:011d1198 <<

79331630 400009a 14 System.Char[] 0 shared static WhitespaceChars

>> Domain:Value 001831e0:011d17d4 <<

* and we have now managed to get the actual TSQL batch executed by SSMS which caused the exception to happen

* this would be enough information to then leave the debugging and go and investigate this from another direction.

* this is effectively what we did in post of the series, by tracing the command through SQL Profiler

So we've seen that we've managed to get the code which is executing, and we've also noted that there is a System.DBNull on the stack next to the NextRunDate object. The point here really though is that because we're dealing with the managed code within SSMS alot more is exposed to us using a memory dump. In this case you could continue the debugging to look at the actual data table which is returned by the stored procedure, and then read through it see which row of the data table contains the Null, which then leads you right back to the source data corruption.

The thing that should be really occurring to you now though is that you can get all others sorts of information out , from this simple example, or from any dump which you might trigger of SSMS, if you ever get unexpected behavior.

For example, imagine the problem you had captured a dump for was more complex involving connections to multiple servers, you can review some of the other structures in the Connection object.

* dump the connection object again to remind us of its contents