SQL Connection Pool Timeout Debugging
This is a follow up to two blog posts from back in 2009 which talked about leaked connections. In Part 1 and Part 2 of that post, it was about how to determine that you actually filled your pool. This was centered around the following error:
Exception type: System.InvalidOperationException
Message: Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.
InnerException: <none>
StackTrace (generated):
SP IP Function
000000001454DDC0 00000642828425A8 System.Data.ProviderBase.DbConnectionFactory.GetConnection(System.Data.Common.DbConnection)
000000001454DE10 0000064282841BA2 System.Data.ProviderBase.DbConnectionClosed.OpenConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory)
000000001454DE60 000006428284166C System.Data.SqlClient.SqlConnection.Open()
The issue I just worked on was the same exception, but in the case the Pools were not exhausted. In this case, the issue was occurring within BizTalk 2006 R2. We narrowed this down to the following exception:
0:138> !pe e09e13f0
Exception object: 00000000e09e13f0
Exception type: System.Data.SqlClient.SqlException
Message: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
InnerException: <none>
StackTrace (generated):
SP IP Function
0000000015CBDF10 00000642828554A3 System_Data!System.Data.SqlClient.SqlInternalConnection.OnError(System.Data.SqlClient.SqlException, Boolean)+0x103
0000000015CBDF60 0000064282854DA6 System_Data!System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(System.Data.SqlClient.TdsParserStateObject)+0xf6
0000000015CBDFC0 0000064282CDCCF1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadSniError(System.Data.SqlClient.TdsParserStateObject, UInt32)+0x291
0000000015CBE0A0 000006428284ECCA System_Data!System.Data.SqlClient.TdsParserStateObject.ReadSni(System.Data.Common.DbAsyncResult, System.Data.SqlClient.TdsParserStateObject)+0x13a
0000000015CBE140 000006428284E9E1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()+0x91
0000000015CBE1A0 0000064282852763 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadBuffer()+0x33
0000000015CBE1D0 00000642828526A1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadByte()+0x21
0000000015CBE200 0000064282851B5C System_Data!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)+0xbc
0000000015CBE2D0 00000642828519E6 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.CompleteLogin(Boolean)+0x36
0000000015CBE320 000006428284A997 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(System.Data.SqlClient.ServerInfo, System.String, Boolean, Int64, System.Data.SqlClient.SqlConnection)+0x147
0000000015CBE3C0 000006428284859F System_Data!System.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(System.String, System.String, Boolean, System.Data.SqlClient.SqlConnection, System.Data.SqlClient.SqlConnectionString, Int64)+0x52f
0000000015CBE530 0000064282847505 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(System.Data.SqlClient.SqlConnection, System.Data.SqlClient.SqlConnectionString, System.String, Boolean)+0x135
0000000015CBE5D0 00000642828471E3 System_Data!System.Data.SqlClient.SqlInternalConnectionTds..ctor(System.Data.ProviderBase.DbConnectionPoolIdentity, System.Data.SqlClient.SqlConnectionString, System.Object, System.String, System.Data.SqlClient.SqlConnection, Boolean)+0x153
0000000015CBE670 0000064282846E36 System_Data!System.Data.SqlClient.SqlConnectionFactory.CreateConnection(System.Data.Common.DbConnectionOptions, System.Object, System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnection)+0x296
0000000015CBE730 0000064282846947 System_Data!System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnectionOptions)+0x37
0000000015CBE790 000006428284689D System_Data!System.Data.ProviderBase.DbConnectionPool.CreateObject(System.Data.Common.DbConnection)+0x29d
0000000015CBE830 000006428292905D System_Data!System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(System.Data.Common.DbConnection)+0x5d
0000000015CBE870 0000064282846412 System_Data!System.Data.ProviderBase.DbConnectionPool.GetConnection(System.Data.Common.DbConnection)+0x6b2
0000000015CBE930 00000642828424B4 System_Data!System.Data.ProviderBase.DbConnectionFactory.GetConnection(System.Data.Common.DbConnection)+0x54
0000000015CBE980 0000064282841BA2 System_Data!System.Data.ProviderBase.DbConnectionClosed.OpenConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory)+0xf2
0000000015CBE9D0 000006428284166C System_Data!System.Data.SqlClient.SqlConnection.Open()+0x10c
0000000015CBEA60 0000064282928C2D Microsoft_BizTalk_Bam_EventObservation!Microsoft.BizTalk.Bam.EventObservation.DirectEventStream.StoreSingleEvent(Microsoft.BizTalk.Bam.EventObservation.IPersistQueryable)+0x8d
0000000015CBEAE0 0000064282928947 Microsoft_BizTalk_Bam_EventObservation!Microsoft.BizTalk.Bam.EventObservation.DirectEventStream.StoreCustomEvent(Microsoft.BizTalk.Bam.EventObservation.IPersistQueryable)+0x47
The end result was to either increase the connection timeout for that connection string, or to look at the performance on the SQL Server and determine why SQL wasn’t able to satisfy the connection. The customer had indicated that this occurred at the month end operations, which probably means that we ramped up pressure on SQL Server. It may have come down to us not having enough Workers within SQL to handle the connection request which resulted in a Timeout after the default timeout which is 15 seconds.
Techie details:
This will look at how we determined what the problem was once we had a memory dump of the process. These debugging instructions are based on a 64-bit dump. The steps should be similar for a 32-bit dump as well. For the dumps, we used the SOS debugging extension which ships with the .NET Framework. You can load the extension in the debugger by using the following command:
0:000> .loadby sos mscorwks
Let’s first find the Connection Pools that are in the dump:
0:138> !dumpheap -stat -type DbConnectionPool
000006428281fce8 4 416 System.Data.ProviderBase.DbConnectionPool+TransactedConnectionPool
000006428085dbc8 28 672 System.Data.ProviderBase.DbConnectionPoolCounters+Counter
000006428281f6d8 8 704 System.Data.ProviderBase.DbConnectionPool+PoolWaitHandles
0000064282810450 4 704 System.Data.ProviderBase.DbConnectionPool
000006428281d320 165 5280 System.Data.ProviderBase.DbConnectionPoolIdentity
This shows the MethodTable that we can use to go get the different items. Of note, you may see multiple items, and may have to go through each one.
0:138> !dumpheap -mt 0x0000064282810450
------------------------------
Heap 4
Address MT Size
00000000c021b348 0000064282810450 176
total 1 objects
------------------------------
Heap 6
Address MT Size
00000000e05add10 0000064282810450 176
total 1 objects
------------------------------
Heap 12
Address MT Size
000000014004b1d8 0000064282810450 176
total 1 objects
------------------------------
Heap 13
Address MT Size
00000001502e6af0 0000064282810450 176
We have 4 pools. Let’s have a look at each pool and see how many connections we have for each.
Pool 1:
0:138> !do 0x00000000c021b348
Name: System.Data.ProviderBase.DbConnectionPool
MethodTable: 0000064282810450
EEClass: 00000642827da538
Size: 176(0xb0) 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
…
00000642827ef760 400153f 18 ...nnectionPoolGroup 0 instance 0000000160036630 _connectionPoolGroup
0000064282818d18 4001540 20 ...nPoolGroupOptions 0 instance 0000000160036608 _connectionPoolGroupOptions
…
000006427843d998 4001551 98 System.Int32 1 instance 7 _totalObjects <-- Only 7 Objects out of a total pool size of 500
…0:138> !do 0000000160036608
Name: System.Data.ProviderBase.DbConnectionPoolGroupOptions
MethodTable: 0000064282818d18
EEClass: 000006428282ce58
Size: 40(0x28) 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
00000642784358f8 4001598 14 System.Boolean 1 instance 1 _poolByIdentity
000006427843d998 4001599 8 System.Int32 1 instance 1 _minPoolSize
000006427843d998 400159a c System.Int32 1 instance 500 _maxPoolSize <-- Total pool size
Pool 2:
0:138> !do 0x00000000e05add10
Name: System.Data.ProviderBase.DbConnectionPool
0000064282818d18 4001540 20 ...nPoolGroupOptions 0 instance e05ad798 _connectionPoolGroupOptions
000006427843d998 4001551 98 System.Int32 1 instance 6 _totalObjects <-- Only 6 Objects out of a total pool size of 1000:138> !do e05ad798
Name: System.Data.ProviderBase.DbConnectionPoolGroupOptions
MT Field Offset Type VT Attr Value Name
00000642784358f8 4001598 14 System.Boolean 1 instance 1 _poolByIdentity
000006427843d998 4001599 8 System.Int32 1 instance 0 _minPoolSize
000006427843d998 400159a c System.Int32 1 instance 100 _maxPoolSize <-- Total pool size
Pool 3:
0:138> !do 0x000000014004b1d8
Name: System.Data.ProviderBase.DbConnectionPool
0000064282818d18 4001540 20 ...nPoolGroupOptions 0 instance d01e8288 _connectionPoolGroupOptions
000006427843d998 4001551 98 System.Int32 1 instance 7 _totalObjects <-- Only 7 Objects out of a total pool size of 5000:138> !do d01e8288
Name: System.Data.ProviderBase.DbConnectionPoolGroupOptions
MT Field Offset Type VT Attr Value Name
00000642784358f8 4001598 14 System.Boolean 1 instance 1 _poolByIdentity
000006427843d998 4001599 8 System.Int32 1 instance 1 _minPoolSize
000006427843d998 400159a c System.Int32 1 instance 500 _maxPoolSize <-- Total pool size
Pool 4:
0:138> !do 0x00000001502e6af0
Name: System.Data.ProviderBase.DbConnectionPool
0000064282818d18 4001540 20 ...nPoolGroupOptions 0 instance 1600f1940 _connectionPoolGroupOptions
000006427843d998 4001551 98 System.Int32 1 instance 4 _totalObjects <-- Only 4 Objects out of a total pool size of 1000:138> !do 1600f1940
Name: System.Data.ProviderBase.DbConnectionPoolGroupOptions
MT Field Offset Type VT Attr Value Name
00000642784358f8 4001598 14 System.Boolean 1 instance 1 _poolByIdentity
000006427843d998 4001599 8 System.Int32 1 instance 0 _minPoolSize
000006427843d998 400159a c System.Int32 1 instance 100 _maxPoolSize <-- Total pool size
The connection pools are dictated by the Connection String used. So, this means 4 different connection strings were used. We can look at the stack objects to see if we can pick apart some more information.
0:138> !dso
OS Thread Id: 0x70b0 (138)
RSP/REG Object Name
...
000000001454df30 00000001602a0f00 System.Data.SqlClient.SqlConnection
000000001454df40 00000000c0ace890 System.String
000000001454df48 00000001602a0cf0 Microsoft.BizTalk.Bam.EventObservation.BAMTraceFragment
000000001454df50 0000000150511568 System.String
000000001454df60 00000001602a0b00 Microsoft.BizTalk.Bam.EventObservation.DirectEventStream
000000001454df70 00000001602a0b00 Microsoft.BizTalk.Bam.EventObservation.DirectEventStream
000000001454df78 00000001602a0cf0 Microsoft.BizTalk.Bam.EventObservation.BAMTraceFragment
000000001454df80 00000001505112d0 System.String
000000001454df88 0000000150511568 System.String
000000001454df90 00000001602a0cf0 Microsoft.BizTalk.Bam.EventObservation.BAMTraceFragment
000000001454dfa8 00000001602a13d0 System.InvalidOperationException
000000001454dfb0 00000001602a0b38 System.Object
000000001454dfb8 000000015050d780 System.Data.SqlClient.SqlCommand
...
Here is the SQL Command Object that was issuing the command when we had the exception.
0:138> !do 000000015050d780
Name: System.Data.SqlClient.SqlCommand
MethodTable: 000006428279dbd0
EEClass: 00000642827d1dc0
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
0000064278436018 400018a 8 System.Object 0 instance 0000000000000000 __identity
00000642828144d8 40008de 10 ...ponentModel.ISite 0 instance 0000000000000000 site
00000642826664d8 40008df 18 ....EventHandlerList 0 instance 0000000000000000 events
0000064278436018 40008dd 210 System.Object 0 static 00000000f0269548 EventDisposed
000006427843d998 40016f2 b0 System.Int32 1 instance 672 ObjectID
0000064278436728 40016f3 20 System.String 0 instance 00000000f0020178 _commandText <-- The query/command issued
000006428279c370 40016f4 b4 System.Int32 1 instance 4 _commandType
000006427843d998 40016f5 b8 System.Int32 1 instance 30 _commandTimeout
000006428279d908 40016f6 bc System.Int32 1 instance 3 _updatedRowSource
00000642784358f8 40016f7 d0 System.Boolean 1 instance 0 _designTimeInvisible
000006428288d490 40016f8 28 ...ent.SqlDependency 0 instance 0000000000000000 _sqlDep
00000642784358f8 40016f9 d1 System.Boolean 1 instance 0 _inPrepare
000006427843d998 40016fa c0 System.Int32 1 instance -1 _prepareHandle
00000642784358f8 40016fb d2 System.Boolean 1 instance 0 _hiddenPrepare
00000642827e3128 40016fc 30 ...rameterCollection 0 instance 000000015050d940 _parameters
00000642827eea48 40016fd 38 ...ent.SqlConnection 0 instance 000000015050f308 _activeConnection <-- The SqlConnection that we used for this command
00000642784358f8 40016fe d3 System.Boolean 1 instance 0 _dirty
…
In this case, we know the SqlConnection isn’t valid because we erred trying to get it from the Pool. The Command Text would be interesting has this been a Query timeout, but for a connection Timeout, it is irrelevant. We can poke at the strings on the stack and we will find the Connection String used for this operation.
0:138> !do 00000001505112d0
Name: System.String
MethodTable: 0000064278436728
EEClass: 000006427803e520
Size: 330(0x14a) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: server=MyServer; database= MyDatabase;Integrated Security=SSPI;Connect Timeout=25; pooling=true; Max Pool Size=500; Min Pool Size=1
From this, we can see Max Pool Size is at 500, so that narrows it down to two of the four Pools listed above. When we went through the pools previously, I noticed that one of the pools had something that the others didn’t. And, it happened to be one of the pools with the Pool Size of 500. Let’s look at the full input of the pool in question.
0:138> !do 0x000000014004b1d8
Name: System.Data.ProviderBase.DbConnectionPool
MethodTable: 0000064282810450
EEClass: 00000642827da538
Size: 176(0xb0) 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
000006427843d998 400153c 88 System.Int32 1 instance 200000 _cleanupWait
000006428281d320 400153d 8 ...ctionPoolIdentity 0 instance 000000014004b1b8 _identity
00000642827ef2d0 400153e 10 ...ConnectionFactory 0 instance 0000000140022860 _connectionFactory
00000642827ef760 400153f 18 ...nnectionPoolGroup 0 instance 00000000d01e82b0 _connectionPoolGroup <-- We can get the connection string from this object
0000064282818d18 4001540 20 ...nPoolGroupOptions 0 instance 00000000d01e8288 _connectionPoolGroupOptions
000006428281d3c0 4001541 28 ...nPoolProviderInfo 0 instance 0000000000000000 _connectionPoolProviderInfo
00000642828102f8 4001542 8c System.Int32 1 instance 1 _state
000006428281d4b8 4001543 30 ...InternalListStack 0 instance 000000014004b288 _stackOld
000006428281d4b8 4001544 38 ...InternalListStack 0 instance 000000014004b2a0 _stackNew
0000064278424d50 4001545 40 ...ding.WaitCallback 0 instance 000000014004c570 _poolCreateRequest
0000064278425c90 4001546 48 ...Collections.Queue 0 instance 0000000000000000 _deactivateQueue
0000064278424d50 4001547 50 ...ding.WaitCallback 0 instance 0000000000000000 _deactivateCallback
000006427843d998 4001548 90 System.Int32 1 instance 0 _waitCount
000006428281f6d8 4001549 58 ...l+PoolWaitHandles 0 instance 000000014004b3a8 _waitHandles
00000642784369f0 400154a 60 System.Exception 0 instance 00000000e09e13f0 _resError <-- We had an error on this pool
00000642784358f8 400154b a0 System.Boolean 1 instance 1 _errorOccurred
000006427843d998 400154c 94 System.Int32 1 instance 10000 _errorWait
0000064278468a80 400154d 68 ...m.Threading.Timer 0 instance 00000001505bc420 _errorTimer
0000064278468a80 400154e 70 ...m.Threading.Timer 0 instance 000000014004c5f0 _cleanupTimer
000006428281fce8 400154f 78 ...tedConnectionPool 0 instance 000000014004c3e8 _transactedConnectionPool
0000000000000000 4001550 80 0 instance 000000014004b400 _objectList
000006427843d998 4001551 98 System.Int32 1 instance 7 _totalObjects
000006427843d998 4001553 9c System.Int32 1 instance 8 _objectID
0000064278425e20 400153b c00 System.Random 0 static 00000000e0188968 _random
000006427843d998 4001552 968 System.Int32 1 static 18 _objectTypeCount
First, lets see if we can line up the connection string for this Pool with what was on the stack to make sure we are looking at the right pool.
0:138> !do 00000000d01e82b0
Name: System.Data.ProviderBase.DbConnectionPoolGroup
MethodTable: 00000642827ef760
EEClass: 00000642827da418
Size: 72(0x48) 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
0000064282816978 4001584 8 ...ConnectionOptions 0 instance 0000000170021600 _connectionOptions
0000064282818d18 4001585 10 ...nPoolGroupOptions 0 instance 00000000d01e8288 _poolGroupOptions
00000642823f2650 4001586 18 ....HybridDictionary 0 instance 00000000b00fb528 _poolCollection
000006427843d998 4001587 30 System.Int32 1 instance 1 _poolCount
000006427843d998 4001588 34 System.Int32 1 instance 1 _state
00000642828193b0 4001589 20 ...GroupProviderInfo 0 instance 00000000d01e82f8 _providerInfo
0000000000000000 400158a 28 ...DbMetaDataFactory 0 instance 0000000000000000 _metaDataFactory
000006427843d998 400158c 38 System.Int32 1 instance 7 _objectID
000006427843d998 400158b 978 System.Int32 1 static 20 _objectTypeCount0:138> !do 0000000170021600
Name: System.Data.SqlClient.SqlConnectionString
MethodTable: 0000064282817158
EEClass: 00000642828234e0
Size: 184(0xb8) 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
0000064278436728 4000bef 8 System.String 0 instance 0000000150020230 _usersConnectionString
000006427843e080 4000bf0 10 ...ections.Hashtable 0 instance 00000001700216b8 _parsetable
00000642828180a0 4000bf1 18 ...mon.NameValuePair 0 instance 0000000170021878 KeyChain
00000642784358f8 4000bf2 28 System.Boolean 1 instance 0 HasPasswordKeyword
00000642784358f8 4000bf3 29 System.Boolean 1 instance 0 UseOdbcRules
000006427843cf18 4000bf4 20 ...ity.PermissionSet 0 instance 00000000d01e8330 _permissionset
00000642825a4958 4000beb 3e0 ...Expressions.Regex 0 static 00000000f026d658 ConnectionStringValidKeyRegex
00000642825a4958 4000bec 3e8 ...Expressions.Regex 0 static 00000000d01e7798 ConnectionStringValidValueRegex
00000642825a4958 4000bed 3f0 ...Expressions.Regex 0 static 0000000080032770 ConnectionStringQuoteValueRegex
00000642825a4958 4000bee 3f8 ...Expressions.Regex 0 static 0000000080034800 ConnectionStringQuoteOdbcValueRegex
…0:138> !do 0000000150020230
Name: System.String
MethodTable: 0000064278436728
EEClass: 000006427803e520
Size: 330(0x14a) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: server=MyServer; database= MyDatabase;Integrated Security=SSPI;Connect Timeout=25; pooling=true; Max Pool Size=500; Min Pool Size=1
We have a match! So, now lets look at the error that was on the pool.
0:138> !pe 00000000e09e13f0
Exception object: 00000000e09e13f0
Exception type: System.Data.SqlClient.SqlException
Message: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
InnerException: <none>
StackTrace (generated):
SP IP Function
0000000015CBDF10 00000642828554A3 System_Data!System.Data.SqlClient.SqlInternalConnection.OnError(System.Data.SqlClient.SqlException, Boolean)+0x103
0000000015CBDF60 0000064282854DA6 System_Data!System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(System.Data.SqlClient.TdsParserStateObject)+0xf6
0000000015CBDFC0 0000064282CDCCF1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadSniError(System.Data.SqlClient.TdsParserStateObject, UInt32)+0x291
0000000015CBE0A0 000006428284ECCA System_Data!System.Data.SqlClient.TdsParserStateObject.ReadSni(System.Data.Common.DbAsyncResult, System.Data.SqlClient.TdsParserStateObject)+0x13a
0000000015CBE140 000006428284E9E1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()+0x91
0000000015CBE1A0 0000064282852763 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadBuffer()+0x33
0000000015CBE1D0 00000642828526A1 System_Data!System.Data.SqlClient.TdsParserStateObject.ReadByte()+0x21
0000000015CBE200 0000064282851B5C System_Data!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)+0xbc
0000000015CBE2D0 00000642828519E6 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.CompleteLogin(Boolean)+0x36
0000000015CBE320 000006428284A997 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(System.Data.SqlClient.ServerInfo, System.String, Boolean, Int64, System.Data.SqlClient.SqlConnection)+0x147
0000000015CBE3C0 000006428284859F System_Data!System.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(System.String, System.String, Boolean, System.Data.SqlClient.SqlConnection, System.Data.SqlClient.SqlConnectionString, Int64)+0x52f
0000000015CBE530 0000064282847505 System_Data!System.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(System.Data.SqlClient.SqlConnection, System.Data.SqlClient.SqlConnectionString, System.String, Boolean)+0x135
0000000015CBE5D0 00000642828471E3 System_Data!System.Data.SqlClient.SqlInternalConnectionTds..ctor(System.Data.ProviderBase.DbConnectionPoolIdentity, System.Data.SqlClient.SqlConnectionString, System.Object, System.String, System.Data.SqlClient.SqlConnection, Boolean)+0x153
0000000015CBE670 0000064282846E36 System_Data!System.Data.SqlClient.SqlConnectionFactory.CreateConnection(System.Data.Common.DbConnectionOptions, System.Object, System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnection)+0x296
0000000015CBE730 0000064282846947 System_Data!System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionPool, System.Data.Common.DbConnectionOptions)+0x37
0000000015CBE790 000006428284689D System_Data!System.Data.ProviderBase.DbConnectionPool.CreateObject(System.Data.Common.DbConnection)+0x29d
0000000015CBE830 000006428292905D System_Data!System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(System.Data.Common.DbConnection)+0x5d
0000000015CBE870 0000064282846412 System_Data!System.Data.ProviderBase.DbConnectionPool.GetConnection(System.Data.Common.DbConnection)+0x6b2
0000000015CBE930 00000642828424B4 System_Data!System.Data.ProviderBase.DbConnectionFactory.GetConnection(System.Data.Common.DbConnection)+0x54
0000000015CBE980 0000064282841BA2 System_Data!System.Data.ProviderBase.DbConnectionClosed.OpenConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory)+0xf2
0000000015CBE9D0 000006428284166C System_Data!System.Data.SqlClient.SqlConnection.Open()+0x10c
0000000015CBEA60 0000064282928C2D Microsoft_BizTalk_Bam_EventObservation!Microsoft.BizTalk.Bam.EventObservation.DirectEventStream.StoreSingleEvent(Microsoft.BizTalk.Bam.EventObservation.IPersistQueryable)+0x8d
0000000015CBEAE0 0000064282928947 Microsoft_BizTalk_Bam_EventObservation!Microsoft.BizTalk.Bam.EventObservation.DirectEventStream.StoreCustomEvent(Microsoft.BizTalk.Bam.EventObservation.IPersistQueryable)+0x47
As we can see, it is a normal Connection Timeout error. Which makes sense, as our pools were not exhausted. Of note, they had set their Connection Timeout to 25 seconds in the connection string. Which means they would need to bump it higher, or look at what is going on with SQL Server at the time this occurs. Not much more we can get from the dump.
Adam W. Saxton | Microsoft Escalation Services
https://twitter.com/awsaxton
Comments
Anonymous
October 22, 2013
Thanks for the detailed walk through and analysis. I have had to do this a couple times and it definitely makes the process of debugging easier seeing what to look at and knowing some of the reasoning behind the results you see.Anonymous
October 23, 2013
I actually wrote a WinDBG extension to do this. It dumps all connection pools in the process, along with all the open connections, commands, and SQL being run at the time. Not to plug my blog, but you can check it out here: www.steveniemitz.com/.../Introducing-SPT-for-NET-45.aspx