We have a .NET background processing application (a console application) that performs some arbitrary workloads (mostly internal users supply a .NET DLL that implements the Execute interface). The background processing application then loads the DLL through reflection and executes it.
One of the supplied DLLs, apparently, has a COM object in it, which is incorrectly located (probably).
Since the processing time is quite long, and we have COM objects created on the main thread and not properly placed, this causes Finalizer Thread to be blocked, which subsequently causes the process to accumulate a significant number of unreleased descriptors (this can reach hundreds of thousands)
I tried to debug the dump of this process using WinDbg, and I can clearly see that the finalizer thread is blocked in the main thread in the COM call.
First we look at the unmanaged stack in the finalizer thread (I assume I'm trying to contact another thread to complete the COM object):
0:002> kb # ChildEBP RetAddr Args to Child 00 0372eec0 74a92cc7 00000968 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 01 0372ef34 74a92c02 00000968 ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0x99 02 0372ef48 74dd9839 00000968 ffffffff 010846e4 KERNELBASE!WaitForSingleObject+0x12 03 (Inline) -------- -------- -------- -------- combase!MTAThreadWaitForCall+0x43 [d:\blue\com\combase\dcomrem\channelb.cxx @ 5657] 04 0372ef78 74e7d524 01083ef0 0111a198 0372f1e4 combase!MTAThreadDispatchCrossApartmentCall+0x1ed [d:\blue\com\combase\dcomrem\chancont.cxx @ 193] 05 (Inline) -------- -------- -------- -------- combase!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x33a2 [d:\blue\com\combase\dcomrem\channelb.cxx @ 5052] 06 0372f0cc 74d5caea 010846e4 0372f1e4 0372f1ac combase!CRpcChannelBuffer::SendReceive2+0x62d [d:\blue\com\combase\dcomrem\channelb.cxx @ 4796] 07 (Inline) -------- -------- -------- -------- combase!ClientCallRetryContext::SendReceiveWithRetry+0x2e [d:\blue\com\combase\dcomrem\callctrl.cxx @ 1090] 08 (Inline) -------- -------- -------- -------- combase!CAptRpcChnl::SendReceiveInRetryContext+0x81 [d:\blue\com\combase\dcomrem\callctrl.cxx @ 715] 09 0372f12c 74da1789 010846e4 0372f1e4 0372f1ac combase!DefaultSendReceive+0x9e [d:\blue\com\combase\dcomrem\callctrl.cxx @ 671] 0a (Inline) -------- -------- -------- -------- combase!CAptRpcChnl::SendReceive+0x38 [d:\blue\com\combase\dcomrem\callctrl.cxx @ 752] 0b 0372f190 74e7a010 010846e4 0372f1e4 0372f1ac combase!CCtxComChnl::SendReceive+0x248 [d:\blue\com\combase\dcomrem\ctxchnl.cxx @ 735] 0c 0372f1b4 749f5769 0732ade4 0372f210 749f5740 combase!NdrExtpProxySendReceive+0x5c [d:\blue\com\combase\ndr\ndrole\proxy.cxx @ 2017] 0d 0372f1cc 74a76c1b 3037cf71 0732ade4 0372f630 rpcrt4!NdrpProxySendReceive+0x29 0e 0372f5f8 74e79e1e 74d4d8f8 74d52ff0 0372f630 rpcrt4!NdrClientCall2+0x22b 0f 0372f618 74d5c46f 0372f630 00000008 0372f6b8 combase!ObjectStublessClient+0x6c [d:\blue\com\combase\ndr\ndrole\i386\stblsclt.cxx @ 215] 10 0372f628 74da1c07 0732ade4 0372f668 01075c10 combase!ObjectStubless+0xf [d:\blue\com\combase\ndr\ndrole\i386\stubless.asm @ 171] 11 0372f6b8 74da3024 01075c00 74296f1e 0372f77c combase!CObjectContext::InternalContextCallback+0x1e4 [d:\blue\com\combase\dcomrem\context.cxx @ 4428] 12 0372f70c 74296db9 01075c10 74296f1e 0372f77c combase!CObjectContext::ContextCallback+0xbc [d:\blue\com\combase\dcomrem\context.cxx @ 4332] 13 0372f804 74296e8a 74296771 0372f894 30ec4c53 clr!CtxEntry::EnterContext+0x243 14 0372f83c 74296ecb 74296771 0372f894 00000000 clr!RCW::EnterContext+0x3a 15 0372f858 74296ca8 01075cb8 30ec4c07 747f62e8 clr!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xc0 16 0372f8b4 74296453 30ec4d6b 747f5660 00000000 clr!RCWCleanupList::CleanupAllWrappers+0x14d 17 0372f904 742966d8 0103d6d8 00000001 30ec4cb7 clr!SyncBlockCache::CleanupSyncBlocks+0xd0 18 0372f91c 74294a12 30ec4d47 0372fa38 0372fab0 clr!Thread::DoExtraWorkForFinalizer+0x7f 19 0372f964 741ad6b7 0372fab0 0104dbd0 0372fab0 clr!WKS::GCHeap::FinalizerThreadWorker+0x232 1a 0372f978 741ad721 30ec4e73 0372fab0 00000000 clr!Thread::DoExtraWorkForFinalizer+0x1bd 1b 0372fa1c 741ad7ee 30ec4e17 00000000 00000040 clr!Thread::DoExtraWorkForFinalizer+0x240 1c 0372fa78 742bac66 30ec4e9b 742bab00 00000000 clr!Thread::DoExtraWorkForFinalizer+0x5f0 1d 0372faf4 742a5ffd 00000000 00000000 00000000 clr!WKS::GCHeap::FinalizerThreadStart+0x1a0 1e 0372fb94 75127c04 01036258 75127be0 31b17300 clr!Thread::intermediateThreadProc+0x4d 1f 0372fba8 7723ab8f 01036258 33bfcebd 00000000 kernel32!BaseThreadInitThunk+0x24 20 0372fbf0 7723ab5a ffffffff 7721ffcf 00000000 ntdll!__RtlUserThreadStart+0x2f 21 0372fc00 00000000 742a5fb4 01036258 00000000 ntdll!_RtlUserThreadStart+0x1b
Now let's try to trace the call (01083ef0):
0:002> dc 010846e4 010846e4 74d4d400 74d61e2c 74d5a65c adb1682c ...t,..t\..t,h.. 010846f4 429b3908 2b59b182 e6a936e1 00000003 .9.B..Y+.6...... 01084704 0000002a 04931d40 00000000 01083ef0 * ...@........ >.. 01084714 010849d8 0732cbc0 010910c0 74d4b2e0 .I....2........t 01084724 00070005 00000003 0009b798 00000000 ................ 01084734 00000000 0108478c f1eef1ee 00650054 .....G......Te 01084744 00680063 00470020 006f006c 00610062 ch .Globa 01084754 002f006c 00610043 00670072 0057006f l./.CargoW
Now we can determine the process identifier (the same as we are in our own process) and the flow identifier 0009b798:
0:002> dc 01083ef0 01083ef0 01083f88 74e8ddd0 00008b8c 0009b798 .?.....t........ 01083f00 c502aa57 72322f52 5c326394 bf12fc0f W...R/2r.c2\.... 01083f10 5c326394 bf12fc0f 00007400 ffff8b8c .c2\.....t...... 01083f20 7579b889 1e59d93e 04000203 01f31fa0 ..yu>.Y......... 01083f30 010794d0 00000000 00000000 00000000 ................ 01083f40 00000001 ffffffff 0102c3b0 0732ade4 ..............2. 01083f50 00000004 00000000 00000000 00000000 ................ 01083f60 0067006e 00070005 00000000 00000000 ng............
Looking at the topics, voila, the finalizer calls the main thread (0009b798)
0:002> !threads Index TID TEB StackBase StackLimit DeAlloc StackSize ThreadProc 0 0009b798 0xff03e000 0x00cf0000 0x00ce5000 0x00bf0000 0x0000b000 0x00000000: 1 000c3e34 0xff03b000 0x015f0000 0x015ef000 0x014f0000 0x00001000 0x00000000: 2 0005c870 0xff035000 0x03730000 0x0372e000 0x03630000 0x00002000 0x00000000: 3 0006518c 0xfef06000 0x04a30000 0x04a2e000 0x049f0000 0x00002000 0x00000000: 4 0006befc 0xfef03000 0x04bf0000 0x04bee000 0x04bb0000 0x00002000 0x00000000: 5 00080128 0xfef00000 0x04d30000 0x04d2d000 0x04c30000 0x00003000 0x00000000: 6 000b3ce0 0xfeef4000 0x06310000 0x0630e000 0x06210000 0x00002000 0x7036df4d: System_Data!SNIAsyncWait 7 00056c18 0xfee8f000 0x075a0000 0x0759f000 0x074a0000 0x00001000 0x00000000: 8 00054374 0xfeef7000 0x0f690000 0x0f68f000 0x0f590000 0x00001000 0x00000000: 9 0002c1f0 0xfee3e000 0x0c9f0000 0x0c9ed000 0x0c8f0000 0x00003000 0x00000000: 10 0009ddb8 0xfee80000 0x07ac0000 0x07abe000 0x079c0000 0x00002000 0x00000000:
In my WinDbg session, I can switch between stack frames in the Finalizer freeze frame, here is an example of SendReceive2 observation (although I can do this, I don’t know where and what to look for):
0:002> dx Debugger.Sessions[0].Processes[35724].Threads[378992].Stack.Frames[6].SwitchTo();dv /t /v Debugger.Sessions[0].Processes[35724].Threads[378992].Stack.Frames[6].SwitchTo() @edi class CRpcChannelBuffer * this = 0x010846e4 0372effc struct tagRPCOLEMESSAGE * pMessage = 0x0372f1e4 0372f004 unsigned long * pstatus = 0x0372f1ac 0372efb4 struct tagRPC_ERROR_ENUM_HANDLE EnumHandle = struct tagRPC_ERROR_ENUM_HANDLE 0372f008 int fLogEventIsActive = 0n0 <unavailable> bool bSuccessBeforeClientNotify = <value unavailable> 0372f0a4 struct _GUID iid = {00000134-0000-0000-C000-000000000046} <unavailable> HRESULT result = <value unavailable> @ebx class CMessageCall * pCall = 0x0111a198 0372f0b4 unsigned long [5] RpcValues = unsigned long [5] <unavailable> bool fInstrumentPrematureStubRundown = <value unavailable> 0372f014 struct tagRPC_EXTENDED_ERROR_INFO ErrorInfo = struct tagRPC_EXTENDED_ERROR_INFO <unavailable> unsigned long cMax = <value unavailable> <unavailable> union WireThat * pOutb = <value unavailable> 0372efcc int bEnumRpcErrorInfo = 0n0 0372efdc HRESULT resultSave = 0x00000000 <unavailable> struct __MIDL_XmitDefs_0003 * pLocalThat = <value unavailable> <unavailable> char * stub_data = <value unavailable> 0372efd4 int bSaveResult = 0n0 <unavailable> long status = <value unavailable> <unavailable> struct ISystemDebugEventFire * g_pEventFire = <value unavailable> <unavailable> union WPP_PROJECT_CONTROL_BLOCK * WPP_GLOBAL_Control = <value unavailable>
I have two questions:
First:
I would like to somehow determine which COM object is causing this problem, so I can advise our internal users to fix the problem in their code (if it is not in the DLL utility ;; t is the source). I tried to bypass some of the "combase" methods present on the finalizer stack, however, I am not very familiar with it, so I don’t know which method can contain the CLSID of the target COM object. Any advice from the community is appreciated.
Second:
Considering that our background processing application may suffer from such abuses, is there a way to change it so that even if the main thread performs a long-term operation (during which and on which terrible COM objects are created), we can still finalize these COMs -objects (and other objects, as well as necessary).
PS I have open WinDbg on this, so you can execute any command you need.
Update1:
Based on the suggestions, I tracked RCW, however it is not clear to me how to proceed further:
0:002> !dumpheap -type System.__ComObject Address MT Size 01a7f348 73386b9c 16 Statistics: MT Count TotalSize Class Name 73386b9c 1 16 System.__ComObject Total 1 objects 0:002> !dumprcw 01a7f348 Managed object: 00000000 Creating thread: 01a7f4b4 IUnknown pointer: 01a7f480 COM Context: 00000000 Managed ref count: 0 IUnknown V-table pointer : 01a7f464 (captured at RCW creation time) Flags: IsDisconnected COM interface pointers: IP Context MT Type 72f6347c 00000000 08000011 System.__ComObject 7326fa50 00000000 73311c2c System.__ComObject 7337a44c 00000000 00010000 System.__ComObject
also:
0:002> $$>a<C:\IgorM\HandleLeak\COM_FROM_RCW_PUBLIC.txt 01a7f348 Make sure you are using Symbols and PSSCOR or SOS is loaded… Closing open log file C:\IgorM\HandleLeak\CommandLog_2_continue.log Opened log file 'TEMP.LOG' Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner 16 0110e240 0 0 00000000 none 01a7f348 System.__ComObject ----------------------------- Total 743 CCW 0 RCW 1 ComClassFactory 0 Free 0 Closing open log file TEMP.LOG SyncBlock address = 0110e240 This is the COM object referenced by the RCW object from address 0110e240: 741f6114 74252315 clr!AssemblySecurityDescriptor::`vector deleting destructor' 741f6118 741bf3f9 clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::IsFullyTrusted 741f611c 741d3b9f clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::CanCallUnmanagedCode 741f6120 742e258e clr!ZapVirtualSection::GetSize 741f6124 741f5b78 clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::GetDomain 741f6128 741d71b0 clr!AssemblySecurityDescriptor::Resolve 741f612c 741d71ac clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::IsResolved 741f6130 742f922a clr!AssemblySecurityDescriptor::GetEvidence 741f6134 742d6458 clr!fusion::logging::BindingScope::GetAssemblyName 741f6138 74317958 clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::SetEvidence 741f613c 741bfefc clr!SecurityDescriptorBase<IApplicationSecurityDescriptor>::GetGrantedPermissionSet 741f6140 741d71d4 clr!AssemblySecurityDescriptor::GetSharedSecDesc 741f6144 742059db clr!AssemblySecurityDescriptor::CanAssert 741f6148 74588b41 clr!AssemblySecurityDescriptor::HasUnrestrictedUIPermission 741f614c 74588b4a clr!AssemblySecurityDescriptor::IsAllCritical 741f6150 74588b6c clr!AssemblySecurityDescriptor::IsAllSafeCritical