SqlDependency cause handle leak in async processing mode
-
22 April 2009 23:57I have windows service working with SQL 2005 and registering some SqlDependency notifications. Sometime ago I rewrite my code to use async SQL processing and change my connection string with "Asynchronous Processing=true" accordingly (I think this is main reason because there are no problem in sync version of my code).
I noticed recently that huge amount of handle leaked in my service - approx 2500 - 3000 per day.
With help of WinDbg I found following:
- leaked handle is Event handle created in System.Threading.EventWaitHandle..ctor(Boolean, System.Threading.EventResetMode, System.String), called from System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object) and constructed during execution for System.Data.Common.DbAsyncResult object
- back trace stack come to SqlDependencyProcessDispatcher+SqlConnectionContainer method which originated request, I checked also SqlDependency._com = "BEGIN CONVERSATION TIMER ('5c0f93d2-8c2f-de11-966f-000423c324af') TIMEOUT = 120; WAITFOR(RECEIVE TOP (1) message_type_name, conversation_handle, cast(message_body AS XML) as message_body from [SqlQueryNotificationService-2aaad72c-3b0e-4141-9804-5008cd507bb9]), TIMEOUT @p2;"
May be this is problem in my code but I can't find any.
So any help will be appreciate.
Thank you in advance.
Here truncated log:
....
Handle = 0x00000d30 - OPEN
Thread ID = 0x00000520, Process ID = 0x00000720
0x0094b2ba: <Unloaded_sspc.dll>+0x0094b2b9
0x792d6f26: mscorlib_ni+0x00216f26
0x792d6f6f: mscorlib_ni+0x00216f6f
0x654f4447: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a4447)+0x00000000
0x654f4649: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a4649)+0x00000000
0x654f46ab: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a46ab)+0x00000000
0x6562e56f: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x4de56f)+0x00000000
0x6562e8b5: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x4de8b5)+0x00000000
0x6558d6e8: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x43d6e8)+0x00000000
0x6558d695: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x43d695)+0x00000000
--------------------------------------
Handle = 0x00000d04 - OPEN
Thread ID = 0x00000520, Process ID = 0x00000720
0x0094b2ba: <Unloaded_sspc.dll>+0x0094b2b9
0x792d6f26: mscorlib_ni+0x00216f26
0x792d6f6f: mscorlib_ni+0x00216f6f
0x654f4447: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a4447)+0x00000000
0x654f4649: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a4649)+0x00000000
0x654f46ab: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x3a46ab)+0x00000000
0x6562e84e: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x4de84e)+0x00000000
0x6558d6e8: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x43d6e8)+0x00000000
0x6558d695: System_Data_ni!_bidW103 <PERF> (System_Data_ni+0x43d695)+0x00000000
0x792c9dff: mscorlib_ni+0x00209dff
--------------------------------------
Displayed 0x25 stack traces for outstanding handles opened since the previous snapshot.
...
0:015> !CLRStack
OS Thread Id: 0x520 (15)
ESP EIP
0516f7a0 6558d695 System.Data.Common.DbAsyncResult.ExecuteCallback(System.Object)
0516f7b4 792c9dff System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
0516f7bc 792e019f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0516f7d4 792ca363 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)
0516f7e8 792ca1f9 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)
0516f978 79e71b4c [GCFrame: 0516f978]
0:015> !DumpStack
OS Thread Id: 0x520 (15)
Current frame: (MethodDesc 0x651b00bc +0x65 System.Data.Common.DbAsyncResult.ExecuteCallback(System.Object))
ChildEBP RetAddr Caller,Callee
0516f7ac 792c9dff (MethodDesc 0x790fc9b0 +0x2f System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object))
0516f7b4 792e019f (MethodDesc 0x7910276c +0x6f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0516f7c8 792ca363 (MethodDesc 0x790fc9c8 +0x53 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)), calling (MethodDesc 0x7910276c +0 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0516f7e0 792ca1f9 (MethodDesc 0x790fc9bc +0x59 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)), calling (MethodDesc 0x790fc9c8 +0 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback))
...
0:015> !DumpStackObjects
OS Thread Id: 0x520 (15)
ESP/REG Object Name
ebx 013cda4c System.Threading.ContextCallback
esi 08769b10 System.Data.Common.DbAsyncResult
edi 08769ac8 System.Threading.ExecutionContext
0516f7a4 0877bb50 System.Threading._ThreadPoolWaitCallback
0516f7a8 0154c0ac System.Threading.ExecutionContext
0516f7b4 0877bb68 System.Threading.ExecutionContext
0516f7c0 0877bb50 System.Threading._ThreadPoolWaitCallback
0516f7c4 0877bb68 System.Threading.ExecutionContext
0516f7d0 0877bb50 System.Threading._ThreadPoolWaitCallback
0516f7d8 0877bb50 System.Threading._ThreadPoolWaitCallback
0:015> !do 08769b10
Name: System.Data.Common.DbAsyncResult
MethodTable: 65675c74
EEClass: 65180540
Size: 40(0x28) 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
7931f670 4000b95 4 System.AsyncCallback 0 instance 08769aa8 _callback
793043b8 4000b96 20 System.Boolean 1 instance 0 _fCompleted
793043b8 4000b97 21 System.Boolean 1 instance 0 _fCompletedSynchronously
79317718 4000b98 8 ....ManualResetEvent 0 instance 08769b38 _manualResetEvent // = handle equals one of handles in leaked list
79330508 4000b99 c System.Object 0 instance 00000000 _owner
79330508 4000b9a 10 System.Object 0 instance 00000000 _stateObject
793308ec 4000b9b 14 System.String 0 instance 015708f0 _endMethodName // = EndExecuteReader
7932d5e0 4000b9c 18 ....ExecutionContext 0 instance 08769ac8 _execContext
6523f54c 4000b9e 1c ...onnectionInternal 0 instance 00000000 _connectionInternal
7932a834 4000b9d 1ec ...g.ContextCallback 0 static 015729cc _contextCallback
0:015> !do 08769b38
Name: System.Threading.ManualResetEvent
MethodTable: 79317718
EEClass: 790e44b0
Size: 24(0x18) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79330508 400018a 4 System.Object 0 instance 00000000 __identity
793331b4 40005be c System.IntPtr 1 instance d30 waitHandle
79317928 40005bf 8 ...es.SafeWaitHandle 0 instance 08769b50 safeWaitHandle
793043b8 40005c0 10 System.Boolean 1 instance 0 hasThreadAffinity
793331b4 40005c1 9a8 System.IntPtr 1 shared static InvalidHandle
>> Domain:Value 001653e8:ffffffff <<
0:015> !do 08769aa8
Name: System.AsyncCallback
MethodTable: 7931f670
EEClass: 790c2ed4
Size: 32(0x20) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79330508 40000ff 4 System.Object 0 instance 01551de4 _target
7932fd60 4000100 8 ...ection.MethodBase 0 instance 00000000 _methodBase
793331b4 4000101 c System.IntPtr 1 instance 6520d0b0 _methodPtr
793331b4 4000102 10 System.IntPtr 1 instance 0 _methodPtrAux
79330508 400010c 14 System.Object 0 instance 00000000 _invocationList
793331b4 400010d 18 System.IntPtr 1 instance 0 _invocationCount
0:015> !do 01551de4
Name: SqlDependencyProcessDispatcher+SqlConnectionContainer
MethodTable: 6567e780
EEClass: 651875e4
Size: 96(0x60) 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
6523d75c 4001830 4 ...ent.SqlConnection 0 instance 01552220 _con
6523db08 4001831 8 ...Client.SqlCommand 0 instance 0155b7f4 _com
6523df90 4001832 c ...ient.SqlParameter 0 instance 0155caec _conversationGuidParam
6523df90 4001833 10 ...ient.SqlParameter 0 instance 0155cb50 _timeoutParam
6567e7c4 4001834 14 ...ntainerHashHelper 0 instance 015511c4 _hashHelper
79328f08 4001835 18 ...l.WindowsIdentity 0 instance 00000000 _windowsIdentity
793308ec 4001836 1c System.String 0 instance 0155218c _queue
793308ec 4001837 20 System.String 0 instance 0155cc48 _receiveQuery
793308ec 4001838 24 System.String 0 instance 08768f98 _beginConversationQuery
793308ec 4001839 28 System.String 0 instance 0155214c _endConversationQuery
793308ec 400183a 2c System.String 0 instance 087691cc _concatQuery
79332b38 400183b 4c System.Int32 1 instance 60000 _defaultWaitforTimeout
793308ec 400183c 30 System.String 0 instance 0155b728 _escapedQueueName
793308ec 400183d 34 System.String 0 instance 0155cddc _sprocName
793308ec 400183e 38 System.String 0 instance 08768f3c _dialogHandle
793308ec 400183f 3c System.String 0 instance 01552714 _cachedServer
793308ec 4001840 40 System.String 0 instance 015572a8 _cachedDatabase
793043b8 4001841 58 System.Boolean 1 instance 0 _errorState
793043b8 4001842 59 System.Boolean 1 instance 0 _stop
793043b8 4001843 5a System.Boolean 1 instance 0 _stopped
793043b8 4001844 5b System.Boolean 1 instance 1 _serviceQueueCreated
79332b38 4001845 50 System.Int32 1 instance 1 _startCount
79316f28 4001846 44 ...m.Threading.Timer 0 instance 00000000 _retryTimer
00000000 4001847 48 0 instance 0155b7c0 _appDomainKeyHash
79332b38 4001848 54 System.Int32 1 instance 1 _objectID
79332b38 4001849 894 System.Int32 1 static 1 _objectTypeCount
0:015> !do 0155b7f4
Name: System.Data.SqlClient.SqlCommand
MethodTable: 6523db08
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
79330508 400018a 4 System.Object 0 instance 00000000 __identity
7a5d29d8 40008c3 8 ...ponentModel.ISite 0 instance 00000000 site
7a5eccac 40008c4 c ....EventHandlerList 0 instance 00000000 events
79330508 40008c2 108 System.Object 0 static 013597f0 EventDisposed
79332b38 40016e3 58 System.Int32 1 instance 2 ObjectID
793308ec 40016e4 10 System.String 0 instance 08768f98 _commandText
6523e654 40016e5 5c System.Int32 1 instance 0 _commandType
79332b38 40016e6 60 System.Int32 1 instance 30 _commandTimeout
65659120 40016e7 64 System.Int32 1 instance 3 _updatedRowSource
793043b8 40016e8 78 System.Boolean 1 instance 0 _designTimeInvisible
6567e560 40016e9 14 ...ent.SqlDependency 0 instance 00000000 _sqlDep
793043b8 40016ea 79 System.Boolean 1 instance 0 _inPrepare
79332b38 40016eb 68 System.Int32 1 instance -1 _prepareHandle
793043b8 40016ec 7a System.Boolean 1 instance 0 _hiddenPrepare
6523e870 40016ed 18 ...rameterCollection 0 instance 0155cbb4 _parameters
6523d75c 40016ee 1c ...ent.SqlConnection 0 instance 01552220 _activeConnection
793043b8 40016ef 7b System.Boolean 1 instance 0 _dirty
65660f28 40016f0 6c System.Int32 1 instance 0 _execType
793040bc 40016f1 20 System.Object[] 0 instance 0156fcac _rpcArrayOf1
652422f8 40016f2 24 ...t._SqlMetaDataSet 0 instance 0877bb8c _cachedMetaData
65241e50 40016f3 28 ...+CachedAsyncState 0 instance 0155b900 _cachedAsyncState
79332b38 40016f4 70 System.Int32 1 instance -1 _rowsAffected
6567cd3c 40016f5 2c ...tificationRequest 0 instance 00000000 _notification
793043b8 40016f6 7c System.Boolean 1 instance 1 _notificationAutoEnlist
6567d310 40016f7 30 ...nt.SqlTransaction 0 instance 00000000 _transaction
65658bac 40016f8 34 ...letedEventHandler 0 instance 00000000 _statementCompletedEventHandler
652417d0 40016f9 38 ...ParserStateObject 0 instance 08760510 _stateObj
793043b8 40016fa 7d System.Boolean 1 instance 0 _pendingCancel
793043b8 40016fb 7e System.Boolean 1 instance 0 _batchRPCMode
00000000 40016fc 3c 0 instance 00000000 _RPCList
793040bc 40016fd 40 System.Object[] 0 instance 00000000 _SqlRPCBatchArray
00000000 40016fe 44 0 instance 00000000 _parameterCollectionList
79332b38 40016ff 74 System.Int32 1 instance 0 _currentlyExecutingBatch
65672b34 4001700 48 ...miRequestExecutor 0 instance 00000000 _smiRequest
6567267c 4001701 4c ...Server.SmiContext 0 instance 00000000 _smiRequestContext
6567d9c8 4001702 50 ...+CommandEventSink 0 instance 00000000 _smiEventSink
656727d0 4001703 54 ...DeferedProcessing 0 instance 00000000 _outParamEventSink
79332b38 40016e2 878 System.Int32 1 static 196 _objectTypeCount
793040bc 4001704 78c System.Object[] 0 static 01554e68 PreKatmaiProcParamsNames
793040bc 4001705 790 System.Object[] 0 static 01554eb4 KatmaiProcParamsNames
0:015> !do 08768f98
Name: System.String
MethodTable: 793308ec
EEClass: 790ed64c
Size: 564(0x234) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: BEGIN CONVERSATION TIMER ('5c0f93d2-8c2f-de11-966f-000423c324af') TIMEOUT = 120; WAITFOR(RECEIVE TOP (1) message_type_name, conversation_handle, cast(message_body AS XML) as message_body from [SqlQueryNotificationService-2aaad72c-3b0e-4141-9804-5008cd507bb9]), TIMEOUT @p2;
Fields:
MT Field Offset Type VT Attr Value Name
79332b38 4000096 4 System.Int32 1 instance 274 m_arrayLength
79332b38 4000097 8 System.Int32 1 instance 273 m_stringLength
793315cc 4000098 c System.Char 1 instance 42 m_firstChar
793308ec 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001653e8:012a1198 <<
7933151c 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001653e8:012a16d4 <<
Semua Balasan
-
23 April 2009 21:24ModeratorCan you provide a sample of the code that creates and executes the async command, as well as the callback code? Also, are you calling the appropriate SqlCommand.End* methods after completion of the async call?
This posting is provided "AS IS" with no warranties, and confers no rights. -
23 April 2009 22:47I will try to isolate code for reproduction this issue and post it here.
As for your question, I always call End* methods but handle leaks in idle mode, i.e. when no DB changes happens at all and my code sleeping except looking for notification.
I want to emphasize: handle leaked during execution SqlDependency internal work. I do not issue any command at this time . Take a look thru debug log.
Here basic structure of my code when I test for this issue:
SqlCommands.ConnString store my current connection string: Server=dbserver; Database=DB; Trusted_Connection=True;Connection Timeout=600; Asynchronous Processing=true;
Connection Timeout=600 and Trusted_Connection=True; is no matter, I tried without it with default / using SQl Server auth
...
SqlDependency.Start(SqlCommands.ConnString);
...
<Load cache from DB into memory>:
// Here omitted exception handling and etc.. just code structure
using (var connection = new SqlConnection(SqlCommands.ConnString))
{
var command = new SqlCommand("[LoadData]", connection)
{
CommandType = CommandType.StoredProcedure,
CommandTimeout = Settings.Default.CommandTimeout
};
DataDependency = new SqlDependency(command);
DataDependency.OnChange += DataDependencyOnChange;
connection.Open();
command.BeginExecuteReader(..., null);
...
using (SqlDataReader reader = command.EndExecuteReader(asyncResult))
{
while (reader.Read())
{
...
}
}
}
...
<idle mode waiting for notification >
After loading data into memory I turn off all incoming requests, so service stays in idle mode incrementing open EVENT handles. DB also stays untouched.
I forget to describe my testing environment in first post. I tested this on Windows XP, Windows 2003 Standard SP2, Vista x64 with SQL 2005 Standard/2008 Express on .NET 3.5 SP1 with lastest updates. Issue persist.
Thank you for reply! -
04 Mei 2009 1:16ModeratorThanks for all the details and debugging work Nick. Yes, we have a process wide background thread running and looping and processing the SqlDependency work. From your debug log I can see the command executed is what this background worker does. I suspect our SqlDependency code does not sniff the connection string and check that Asynchronous Processing=true, and thus is spinning off leaking these commands. I'll file a bug to track this on Monday.
-
04 Mei 2009 1:27Moderator I filed a bug on this internally today, I'll post back once we investigate.
- Ditandai sebagai Jawaban oleh Matt Neerincx [MSFT]Moderator 04 Mei 2009 1:39
-
04 Mei 2009 17:30Thank you a lot, Matt!
Hope you can give some workaround. I can test whenever it gone because in my program handle leaks are pretty stable.
I have some additional details, maybe it will be helpful. Look on following debug log:
!gcroot 01573454
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 354
Scan Thread 2 OSTHread 1bc
Scan Thread 6 OSTHread 478
Scan Thread 8 OSTHread 504
Scan Thread 9 OSTHread 690
Scan Thread 13 OSTHread 26c
ecx:Root:09242ffc(System.Threading.WaitCallback)->
082d07a8(System.Data.Common.DbAsyncResult)->
082d0740(System.AsyncCallback)->
01571090(SqlDependencyProcessDispatcher+SqlConnectionContainer)->
0157802c(System.Data.SqlClient.SqlCommand)->
01572dd4(System.Data.SqlClient.TdsParserStateObject)->
0157342c(System.Data.Common.DbAsyncResult)->
01573454(System.Threading.ManualResetEvent)
Scan Thread 16 OSTHread 7f0
DOMAIN(001653E8):HANDLE(Strong):9320b0:Root:01572dd4(System.Data.SqlClient.TdsParserStateObject)->
0157342c(System.Data.Common.DbAsyncResult)
0:013> !do 09242ffc
Name: System.Threading.WaitCallback
0:013> !do 082d07a8
Name: System.Data.Common.DbAsyncResult
MethodTable: 65675c74
EEClass: 65180540
Size: 40(0x28) 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
7931f670 4000b95 4 System.AsyncCallback 0 instance 082d0740 _callback
793043b8 4000b96 20 System.Boolean 1 instance 0 _fCompleted
793043b8 4000b97 21 System.Boolean 1 instance 0 _fCompletedSynchronously
79317718 4000b98 8 ....ManualResetEvent 0 instance 082d07d0 _manualResetEvent
79330508 4000b99 c System.Object 0 instance 00000000 _owner
79330508 4000b9a 10 System.Object 0 instance 00000000 _stateObject
793308ec 4000b9b 14 System.String 0 instance 0158fa1c _endMethodName
7932d5e0 4000b9c 18 ....ExecutionContext 0 instance 082d0760 _execContext
6523f54c 4000b9e 1c ...onnectionInternal 0 instance 00000000 _connectionInternal
7932a834 4000b9d 1ec ...g.ContextCallback 0 static 01590b48 _contextCallback
Name: System.String
MethodTable: 793308ec
EEClass: 790ed64c
Size: 50(0x32) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: EndExecuteReader
Fields:
MT Field Offset Type VT Attr Value Name
79332b38 4000096 4 System.Int32 1 instance 17 m_arrayLength
79332b38 4000097 8 System.Int32 1 instance 16 m_stringLength
793315cc 4000098 c System.Char 1 instance 45 m_firstChar
793308ec 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001653e8:012a1198 <<
7933151c 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001653e8:012a16d4 <<
0:013> !do 082d0740
Name: System.AsyncCallback
MethodTable: 7931f670
EEClass: 790c2ed4
Size: 32(0x20) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79330508 40000ff 4 System.Object 0 instance 01571090 _target
7932fd60 4000100 8 ...ection.MethodBase 0 instance 00000000 _methodBase
793331b4 4000101 c System.IntPtr 1 instance 6520d0b0 _methodPtr
793331b4 4000102 10 System.IntPtr 1 instance 0 _methodPtrAux
79330508 400010c 14 System.Object 0 instance 00000000 _invocationList
793331b4 400010d 18 System.IntPtr 1 instance 0 _invocationCount
0:013> !do 01571090
Name: SqlDependencyProcessDispatcher+SqlConnectionContainer
MethodTable: 6567e780
EEClass: 651875e4
Size: 96(0x60) 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
6523d75c 4001830 4 ...ent.SqlConnection 0 instance 015714cc _con
6523db08 4001831 8 ...Client.SqlCommand 0 instance 0157802c _com
6523df90 4001832 c ...ient.SqlParameter 0 instance 0157bbc4 _conversationGuidParam
6523df90 4001833 10 ...ient.SqlParameter 0 instance 0157bc28 _timeoutParam
6567e7c4 4001834 14 ...ntainerHashHelper 0 instance 01570470 _hashHelper
79328f08 4001835 18 ...l.WindowsIdentity 0 instance 00000000 _windowsIdentity
793308ec 4001836 1c System.String 0 instance 01571438 _queue
793308ec 4001837 20 System.String 0 instance 0157bd20 _receiveQuery
793308ec 4001838 24 System.String 0 instance 01581a84 _beginConversationQuery
793308ec 4001839 28 System.String 0 instance 015713f8 _endConversationQuery
793308ec 400183a 2c System.String 0 instance 01581cb8 _concatQuery
79332b38 400183b 4c System.Int32 1 instance 60000 _defaultWaitforTimeout
793308ec 400183c 30 System.String 0 instance 01577f60 _escapedQueueName
793308ec 400183d 34 System.String 0 instance 0157beb4 _sprocName
793308ec 400183e 38 System.String 0 instance 01581a28 _dialogHandle
793308ec 400183f 3c System.String 0 instance 015719c0 _cachedServer
793308ec 4001840 40 System.String 0 instance 01573ae0 _cachedDatabase
793043b8 4001841 58 System.Boolean 1 instance 0 _errorState
793043b8 4001842 59 System.Boolean 1 instance 0 _stop
793043b8 4001843 5a System.Boolean 1 instance 0 _stopped
793043b8 4001844 5b System.Boolean 1 instance 1 _serviceQueueCreated
79332b38 4001845 50 System.Int32 1 instance 1 _startCount
79316f28 4001846 44 ...m.Threading.Timer 0 instance 00000000 _retryTimer
00000000 4001847 48 0 instance 01577ff8 _appDomainKeyHash
79332b38 4001848 54 System.Int32 1 instance 1 _objectID
79332b38 4001849 894 System.Int32 1 static 1 _objectTypeCount
0:013> !do 0157802c
Name: System.Data.SqlClient.SqlCommand
MethodTable: 6523db08
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
79330508 400018a 4 System.Object 0 instance 00000000 __identity
7a5d29d8 40008c3 8 ...ponentModel.ISite 0 instance 00000000 site
7a5eccac 40008c4 c ....EventHandlerList 0 instance 00000000 events
79330508 40008c2 108 System.Object 0 static 013599b8 EventDisposed
79332b38 40016e3 58 System.Int32 1 instance 1 ObjectID
793308ec 40016e4 10 System.String 0 instance 01581a84 _commandText
6523e654 40016e5 5c System.Int32 1 instance 0 _commandType
79332b38 40016e6 60 System.Int32 1 instance 30 _commandTimeout
65659120 40016e7 64 System.Int32 1 instance 3 _updatedRowSource
793043b8 40016e8 78 System.Boolean 1 instance 0 _designTimeInvisible
6567e560 40016e9 14 ...ent.SqlDependency 0 instance 00000000 _sqlDep
793043b8 40016ea 79 System.Boolean 1 instance 0 _inPrepare
79332b38 40016eb 68 System.Int32 1 instance -1 _prepareHandle
793043b8 40016ec 7a System.Boolean 1 instance 0 _hiddenPrepare
6523e870 40016ed 18 ...rameterCollection 0 instance 0157bc8c _parameters
6523d75c 40016ee 1c ...ent.SqlConnection 0 instance 015714cc _activeConnection
793043b8 40016ef 7b System.Boolean 1 instance 0 _dirty
65660f28 40016f0 6c System.Int32 1 instance 0 _execType
793040bc 40016f1 20 System.Object[] 0 instance 0158edd8 _rpcArrayOf1
652422f8 40016f2 24 ...t._SqlMetaDataSet 0 instance 092bb83c _cachedMetaData
65241e50 40016f3 28 ...+CachedAsyncState 0 instance 015785f8 _cachedAsyncState
79332b38 40016f4 70 System.Int32 1 instance -1 _rowsAffected
6567cd3c 40016f5 2c ...tificationRequest 0 instance 00000000 _notification
793043b8 40016f6 7c System.Boolean 1 instance 1 _notificationAutoEnlist
6567d310 40016f7 30 ...nt.SqlTransaction 0 instance 00000000 _transaction
65658bac 40016f8 34 ...letedEventHandler 0 instance 00000000 _statementCompletedEventHandler
652417d0 40016f9 38 ...ParserStateObject 0 instance 01572dd4 _stateObj
793043b8 40016fa 7d System.Boolean 1 instance 0 _pendingCancel
793043b8 40016fb 7e System.Boolean 1 instance 0 _batchRPCMode
00000000 40016fc 3c 0 instance 00000000 _RPCList
793040bc 40016fd 40 System.Object[] 0 instance 00000000 _SqlRPCBatchArray
00000000 40016fe 44 0 instance 00000000 _parameterCollectionList
79332b38 40016ff 74 System.Int32 1 instance 0 _currentlyExecutingBatch
65672b34 4001700 48 ...miRequestExecutor 0 instance 00000000 _smiRequest
6567267c 4001701 4c ...Server.SmiContext 0 instance 00000000 _smiRequestContext
6567d9c8 4001702 50 ...+CommandEventSink 0 instance 00000000 _smiEventSink
656727d0 4001703 54 ...DeferedProcessing 0 instance 00000000 _outParamEventSink
79332b38 40016e2 878 System.Int32 1 static 194 _objectTypeCount
793040bc 4001704 78c System.Object[] 0 static 015783ec PreKatmaiProcParamsNames
793040bc 4001705 790 System.Object[] 0 static 01578438 KatmaiProcParamsNames
0:013> !do 0157bc28
Name: System.Data.SqlClient.SqlParameter
MethodTable: 6523df90
EEClass: 6515c2b4
Size: 100(0x64) 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
79330508 400018a 4 System.Object 0 instance 00000000 __identity
6523fcf8 4001919 8 ...qlClient.MetaType 0 instance 0157b4c8 _metaType
65241c08 400191a c ...ient.SqlCollation 0 instance 00000000 _collation
793308ec 400191b 10 System.String 0 instance 00000000 _xmlSchemaCollectionDatabase
793308ec 400191c 14 System.String 0 instance 00000000 _xmlSchemaCollectionOwningSchema
793308ec 400191d 18 System.String 0 instance 00000000 _xmlSchemaCollectionName
793308ec 400191e 1c System.String 0 instance 00000000 _udtTypeName
793308ec 400191f 20 System.String 0 instance 00000000 _typeName
7933172c 4001920 24 System.Type 0 instance 00000000 _udtType
79330a80 4001921 28 System.Exception 0 instance 00000000 _udtLoadError
793308ec 4001922 2c System.String 0 instance 01571264 _parameterName
7933340c 4001923 58 System.Byte 1 instance 0 _precision
7933340c 4001924 59 System.Byte 1 instance 0 _scale
793043b8 4001925 5a System.Boolean 1 instance 0 _hasScale
6523fcf8 4001926 30 ...qlClient.MetaType 0 instance 0157b4c8 _internalMetaType
65243580 4001927 34 ...lClient.SqlBuffer 0 instance 00000000 _sqlBufferReturnValue
793043b8 4001928 5b System.Boolean 1 instance 0 _isSqlParameterSqlType
79330508 4001929 38 System.Object 0 instance 0158f94c _value
79330508 400192a 3c System.Object 0 instance 0157bc8c _parent
6523e9b4 400192b 48 System.Int32 1 instance 0 _direction
79332b38 400192c 4c System.Int32 1 instance 0 _size
79332b38 400192d 50 System.Int32 1 instance 0 _offset
793308ec 400192e 40 System.String 0 instance 00000000 _sourceColumn
65657f60 400192f 54 System.Int32 1 instance 0 _sourceVersion
793043b8 4001930 5c System.Boolean 1 instance 0 _sourceColumnNullMapping
793043b8 4001931 5d System.Boolean 1 instance 0 _isNullable
79330508 4001932 44 System.Object 0 instance 0158f94c _coercedValue
0:013> !do 0157342c
Name: System.Data.Common.DbAsyncResult
MethodTable: 65675c74
EEClass: 65180540
Size: 40(0x28) 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
7931f670 4000b95 4 System.AsyncCallback 0 instance 00000000 _callback
793043b8 4000b96 20 System.Boolean 1 instance 0 _fCompleted
793043b8 4000b97 21 System.Boolean 1 instance 0 _fCompletedSynchronously
79317718 4000b98 8 ....ManualResetEvent 0 instance 01573454 _manualResetEvent
79330508 4000b99 c System.Object 0 instance 01572c50 _owner
79330508 4000b9a 10 System.Object 0 instance 00000000 _stateObject
793308ec 4000b9b 14 System.String 0 instance 012a1198 _endMethodName
7932d5e0 4000b9c 18 ....ExecutionContext 0 instance 00000000 _execContext
6523f54c 4000b9e 1c ...onnectionInternal 0 instance 00000000 _connectionInternal
7932a834 4000b9d 1ec ...g.ContextCallback 0 static 01590b48 _contextCallback
0:013> !do 012a1198
Name: System.String
MethodTable: 793308ec
EEClass: 790ed64c
Size: 18(0x12) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String:
Fields:
MT Field Offset Type VT Attr Value Name
79332b38 4000096 4 System.Int32 1 instance 1 m_arrayLength
79332b38 4000097 8 System.Int32 1 instance 0 m_stringLength
793315cc 4000098 c System.Char 1 instance 0 m_firstChar
793308ec 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001653e8:012a1198 <<
7933151c 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001653e8:012a16d4 <<
>>>> It seems to me: handle prepared for release (look at last dump: !do 012a1198, all fields are nulled) but it still pinned in GCRoot (look at first dump).
Thank you for reply. -
19 Mei 2009 17:27Any progress on this?
-
20 Mei 2009 22:41Moderator
Hi
I just started an investigation of this case. From the repro code you sent, I was not able to reproduce the handle leak. I run it for more than 10 minutes in loops, using Task Manager to see the active handles on the process. The number of handles remained same, I did not notice a leak over the time.
But I did notice that handles remain in memory for some period of time until GC (garbage collector) collects them. Those handles were not of SqlDependency listener (the one you saw in debugger), they are handles of SqlCommand.Execute calls used when you register first time or re-register from notification. To get rid of those handles, simple do not use BeginExecuteReader when registering to receive notifications. Simple use ExecuteNonQuery.
DataDependency = new SqlDependency(command);
DataDependency.OnChange += DataDependencyOnChange;
command.ExecuteNonQuery();
Note that those handles are used by IAsyncResult instance you receive back from BeginExecuteReader (actually DbAsyncResult) on user thread. So, while DbAsyncResult is alive, handle has to be open (hard to change the behavior now from backward compatibility reasons). You can also call GC.Collect() once in a while to force GC to collect the orphanned DbAsyncResult instances and free the handles.
Please confirm if this help. If you still see large handle leak and GC.Collect does not help, please post full code sample that reproduces the leak - I will investigate it.
Regards,
Nissim
Postings are provided "As Is" with no warranties and confer no rights. -
21 Mei 2009 19:25Hi,
Thank you very much for information, it was helpful and problem seems solved .
I want to clarify some assumptions you made in your post from debugger's perspective and my code structure.
I look for changes in 15 tables with help of 15 different SqlDependency objects. Server after working 1 week has about 150 000 open handles. I tried to use GC.Collect() (btw it was my first attempt to fix bug though such practice is not recommended) before I started to dig with WinDbg. Results were same. Later (please look at my last WinDbg session) I found why - handle stay referenced by DbAsyncResult which also stay referenced by SqlDependecy's internal class.
I took handle snapshots during entire week and analyzed difference each time, situation was never changed. So, please note, forced and auto Garbage Collection didn't gathered DbAsyncResult instances because they remains referenced.
Under debugger I saw different handles - some from active SqlDependency listener, some from very old instances. Maybe I copied not enough information, but I had about 800 handles after first work hour and forced GC (GC.Collect()) each 5 minutes . They simply can't be orphaned DbAsyncResult instances waiting for GC (or my knowledge how GC works is too bad...). And dumping different objects under WinDbg just prove it.
So, solution was relative simple, change my async code to sync version since it really don't needed for SqlDependency and use isolated command .
Here summary of problem and solution:
Problem code (I post it before already):
var command = new SqlCommand("[dbo].[LoadData]", connection)
{
CommandType = CommandType.StoredProcedure,
CommandTimeout = Settings.Default.CommandTimeout
};
connection.Open();
DataDependency = new SqlDependency(command);
DataDependency.OnChange += DataDependencyOnChange;
command.BeginExecuteReader(..., null);
...
using (SqlDataReader reader = command.EndExecuteReader(asyncResult))
{
while (reader.Read())
{
...
}
}
Maybe I didn't emphasize enough so this stay unclearly: I didn't create isolated SqlCommand for SqlDependency instead I share SqlCommand used to fill my internal cache in async way .
To try solve problem, I isolated command similar that you suggested:
connection.Open();
var cmd = command.Clone();
DataDependency = new SqlDependency(cmd);
DataDependency.OnChange += DataDependencyOnChange;
cmd.ExecuteNonQuery();
command.BeginExecuteReader(..., null);
On development server seems there are no more handle leak but I did only quick check.
I will confirm that problem solved for sure when check on our production server during next week.
Thank you for help.
-
22 Mei 2009 0:52ModeratorI am glad you solved this issue. I am still worried about the leak that happens in the other (async) use of the command. Even after running your originally-provided sample, I was not able to reproduce the leak.
The issue I am worried about is that SqlDependency internal structures do not hold more than one active command, this command hold only one async result, etc... Objects you see are on active stack - this is expected. It means that to leak 150000 handles, application needs to have similar amount of stacks running now, this sounds weird to me. Thus, I want to understand the exact source of the leak - and for this I need the exact code you use (without business sensitive info of course).
Also, I am worried about what you said "I didn't create isolated SqlCommand for SqlDependency instead I share SqlCommand". SqlCommand, SqlConnection or other SqlClient objects are not thread-safe - using the same instance of connection, command or other resources from multiple threads simultaniously can cause troubles.
Can you please post here the original code that caused leak? Please post full, working, code sample (including Main + multi-threading you used) - replace only the connection string and table names (keep the flow and methods called as is). Please test the code separately for a leak before posting it.
Thanks a lot for your time and effort,
Nissim
Postings are provided "As Is" with no warranties and confer no rights. -
22 Mei 2009 9:24Thank you for quick reply.
The main problem why I still not post sample here that building cache and notification response code consist of ~3700 lines (also it tied with other business logic layer, so to full analyze I must post approx 1.4 MB of sources) I just thought you do not have too much time for spare to analyze that I am doing in it.
I started to write isolated sample to reproduce issue and will post it here.
I aware about thread-safety in Sql* objects (and BCL in general) but decide to share same command object since I use it only for loading cache and notification later. It local to function where I used it. All other required objects (connection, etc.) are local too. I do not use sharing as usual practice but thank you for pay my attention.
Here example of weird statistics from my resource monitoring log:
Server alive 365399345ms = ~ 4.2 days
Statistics period: 00:15:00
Single core server utilization [Lifetime]: 0.0144759760569375%
Total server utilization [Lifetime]: 0.00180949700711719%
Single core server utilization [Snapshot]: 0.0103781962708809%
Total server utilization [Snapshot]: 0.00129727453386012%
Peak paged memory usage: 365 MB
Maximum amount of physical memory: 314 MB
Maximum amount of virtual memory: 593 MB
Nonpaged system memory: 0 MB
Paged memory: 297 MB
Pageable system memory: 3 MB
Private memory: 297 MB
Peak paged memory usage: 365 MB
Number of concurrent worker threads: 1 [Max: 2000]
Number of completion port threads: 0 [Max: 1000]
Total processor time: 02:44:27.0312500
Kernel processor time: 00:34:53.4062500
User processor time: 02:09:33.6250000
Virtual memory: 572 MB
Physical memory: 130 MB
Managed memory: 97 MB
Number of handles opened: 200236
Server platform:
Microsoft(R) Windows(R) Server 2003 Standard x64 Edition
Service Pack 2
Phys mem: 1547320 Kb
Phys cores: 8
Total mem: 8583458816 bytes
My application runs in x86 mode.- Diedit oleh Nick Martyshchenko 22 Mei 2009 9:31
-
27 Mei 2009 4:01ModeratorHi again
I did more investigation on the async calls, it seems like 'the leak' is caused by the fact that IAsyncResult instance (DbAsyncResult behind the scenes) holds a WaitHandle which remains active until collected by GC. If you have an application that performs async SQL operations with high rate, close the handle explicitly:
SqlCommand cmd = cxn.CreateCommand(); // initialize command IAsyncResult asyncResult = cmd.BeginExecuteReader(); // perform other operations using (var rdr = cmd.EndExecuteReader(asyncResult)) { // release the wait handle - not needed if (asyncResult.AsyncWaitHandle != null) asyncResult.AsyncWaitHandle.Close(); // Deal with the results... }
If you do not close the handle explicitly, it will be closed by the GC. If, however, rate of async operations is high, it is recommended to close the handle explicitly.
Regards,
Nissim
Postings are provided "As Is" with no warranties and confer no rights. -
27 Mei 2009 8:23
Hi,
thank you for more info.
We prepare new release and I lack of time for working on this issue but I return to investigation soon.
I know about possibility you talk in your post but as I mention before server idle i.e. after loading cache I do not touch database at all even for reading, so there are no other activity except dependency monitoring.
-
19 Maret 2012 7:07
Hi Nissim,
Has this been addressed? Also, not all async clients would need the WaitHandle allocation by default. This should have been implemented using Lazy allocation and only on a need basis when the client actually access the AsyncWaitHadle property for the first time.
Also, are there any plans to use the Slim version of ManualResetEvent?
Thanks!
-
19 Maret 2012 15:08Moderator
We re-architected ADO.NET in 4.5 with new async support. The new APIs support the Task functionality release in .NET 4.0. With the new support IAsyncResult is no longer needed. Instead the method will return a Task or Task<TResult>.
Take a look at this for more details:
http://msdn.microsoft.com/en-gb/vstudio/async.aspx
Matt
