Crash Dump Analysis Patterns (Part 9h)

In one .NET process memory dump we noticed Managed Stack Trace pointing that the thread was waiting for .NET Finalizer to finish its work:

0:000> !CLRStack
OS Thread Id: 0x60b0 (0)
ESP       EIP
00a585d8 773dca2c [HelperMethodFrame: 00a585d8] System.GC.WaitForPendingFinalizers()
00a58628 10105bbb ComponentA.FreeMemory()

The unmanaged stack trace involved Windows forms and COM object modal loops:

0:000> k
ChildEBP RetAddr
00a58034 7644112f ntdll!NtWaitForMultipleObjects+0xc
00a581c0 75ecd433 KERNELBASE!WaitForMultipleObjectsEx+0xcc
00a58224 7655fab4 user32!MsgWaitForMultipleObjectsEx+0x163
00a5825c 7656097c combase!CCliModalLoop::BlockFn+0×111
00a58314 765591fa combase!ClassicSTAThreadWaitForHandles+0×9e
00a58344 6e59103d combase!CoWaitForMultipleHandles+0×84
00a58364 6e590f9e mscorwks!NT5WaitRoutine+0×51
00a583d0 6e590f02 mscorwks!MsgWaitHelper+0xa5
00a583f0 6e6665e8 mscorwks!Thread::DoAppropriateAptStateWait+0×28
00a58474 6e66667d mscorwks!Thread::DoAppropriateWaitWorker+0×13c
00a584c4 6e666801 mscorwks!Thread::DoAppropriateWait+0×40
00a58520 6e5056b8 mscorwks!CLREvent::WaitEx+0xf7
00a58534 6e59eea3 mscorwks!CLREvent::Wait+0×17
00a58584 6e59ec19 mscorwks!WKS::GCHeap::FinalizerThreadWait+0xfb
00a58620 10105bbb mscorwks!GCInterface::RunFinalizers+0×99

00a58684 6cd8683b 0×10105bbb
00a586a0 6c4f5a52 System_Windows_Forms_ni+0xa5683b
00a586e4 6cd8e8f4 System_Windows_Forms_ni+0×1c5a52
00a586f8 6c529a00 System_Windows_Forms_ni+0xa5e8f4
00a58700 6c529981 System_Windows_Forms_ni+0×1f9a00
00a58714 6c52985a System_Windows_Forms_ni+0×1f9981
00a58778 75ec8e71 System_Windows_Forms_ni+0×1f985a
00a587a4 75ec90d1 user32!_InternalCallWinProc+0×2b
00a58838 75ec932c user32!UserCallWinProcCheckWow+0×18e
00a58898 75ec9529 user32!DispatchClientMessage+0xdc
00a588d8 773e07d6 user32!__fnDWORD+0×49
00a588ec 01293a30 ntdll!KiUserCallbackDispatcher+0×36
00a58998 75ecb0f8 0×1293a30
00a589e8 75ec8e71 user32!DefWindowProcW+0×118
00a58a14 75ec90d1 user32!_InternalCallWinProc+0×2b
00a58aa8 75ecddd5 user32!UserCallWinProcCheckWow+0×18e
00a58ae4 6c52a033 user32!CallWindowProcW+0×8d
00a58b3c 6c5331a9 System_Windows_Forms_ni+0×1fa033
00a58b84 6c529b1e System_Windows_Forms_ni+0×2031a9
00a58bdc 6c53310a System_Windows_Forms_ni+0×1f9b1e
00a58be8 6c5330c0 System_Windows_Forms_ni+0×20310a
00a58bf0 6c532d80 System_Windows_Forms_ni+0×2030c0
00a58c04 6c529a00 System_Windows_Forms_ni+0×202d80
00a58c0c 6c529981 System_Windows_Forms_ni+0×1f9a00
00a58c20 6c52985a System_Windows_Forms_ni+0×1f9981
00a58c84 75ec8e71 System_Windows_Forms_ni+0×1f985a
00a58cb0 75ec90d1 user32!_InternalCallWinProc+0×2b
00a58d44 75ec932c user32!UserCallWinProcCheckWow+0×18e
00a58da4 75ec9529 user32!DispatchClientMessage+0xdc
00a58de4 773e07d6 user32!__fnDWORD+0×49
00a58df8 011efaa0 ntdll!KiUserCallbackDispatcher+0×36
00a58e48 75eca989 0×11efaa0
00a58e7c 765603c3 user32!PeekMessageW+0×135
00a58ed0 76560436 combase!CCliModalLoop::MyPeekMessage+0×31
00a58f10 76560630 combase!CCliModalLoop::PeekRPCAndDDEMessage+0×31
00a58f3c 76560506 combase!CCliModalLoop::FindMessage+0×2b
00a58fa0 765605fb combase!CCliModalLoop::HandleWakeForMsg+0×44
00a58fc4 7656097c combase!CCliModalLoop::BlockFn+0×19d
00a5907c 765591fa combase!ClassicSTAThreadWaitForHandles+0×9e
00a590ac 6e59103d combase!CoWaitForMultipleHandles+0×84
00a590cc 6e590f9e mscorwks!NT5WaitRoutine+0×51
00a59138 6e590f02 mscorwks!MsgWaitHelper+0xa5
00a59158 6e6665e8 mscorwks!Thread::DoAppropriateAptStateWait+0×28
00a591dc 6e66667d mscorwks!Thread::DoAppropriateWaitWorker+0×13c
00a5922c 6e666801 mscorwks!Thread::DoAppropriateWait+0×40
00a59288 6e5056b8 mscorwks!CLREvent::WaitEx+0xf7
00a5929c 6e59eea3 mscorwks!CLREvent::Wait+0×17
00a592ec 6e59ec19 mscorwks!WKS::GCHeap::FinalizerThreadWait+0xfb
00a59388 10105bbb mscorwks!GCInterface::RunFinalizers+0×99

00a593ec 6cd8683b 0×10105bbb
00a59408 6ca863bd System_Windows_Forms_ni+0xa5683b
00a59438 6cd90b7e System_Windows_Forms_ni+0×7563bd
00a59480 6c539eee System_Windows_Forms_ni+0xa60b7e
00a5951c 6c539bf7 System_Windows_Forms_ni+0×209eee
00a59574 6c539a41 System_Windows_Forms_ni+0×209bf7
00a595a4 6ca4fc97 System_Windows_Forms_ni+0×209a41
00a595bc 6ca84598 System_Windows_Forms_ni+0×71fc97
00a59648 6ca847af System_Windows_Forms_ni+0×754598
00a59bc8 0996d41c System_Windows_Forms_ni+0×7547af
00a59c2c 0bc02e6d 0×996d41c
00a59c5c 0996b842 0xbc02e6d
00a59fb8 0fa8fa87 0×996b842
00a5a00c 0fa8f205 0xfa8fa87
00a5a040 0fa8f10b 0xfa8f205
00a5a058 02676666 0xfa8f10b
00a5a094 0fa8f09f 0×2676666
00a5a0a8 0fa8ed0c 0xfa8f09f
00a5a1b8 6dc355dc 0xfa8ed0c
00a5a238 6ca59703 mscorlib_ni+0×2355dc
00a5a2bc 6cd8c376 System_Windows_Forms_ni+0×729703
00a5a31c 6c529a00 System_Windows_Forms_ni+0xa5c376
00a5a324 6c529981 System_Windows_Forms_ni+0×1f9a00
00a5a338 6c52985a System_Windows_Forms_ni+0×1f9981
00a5a378 6cd8c587 System_Windows_Forms_ni+0×1f985a
00a5a3c8 6c511125 System_Windows_Forms_ni+0xa5c587
00a5a3f0 6c52985a System_Windows_Forms_ni+0×1e1125
00a5a454 75ec8e71 System_Windows_Forms_ni+0×1f985a
00a5a480 75ec90d1 user32!_InternalCallWinProc+0×2b
00a5a514 75eca66f user32!UserCallWinProcCheckWow+0×18e
00a5a580 75eca6e0 user32!DispatchMessageWorker+0×208
00a5a58c 0f1c6f4e user32!DispatchMessageW+0×10
00a5a5c0 0f1c58ed ModuleA+0×13c4e
[…]

We found Finalizer Special Thread:

0:002> k
ChildEBP RetAddr
0316ecc8 76432cc7 ntdll!NtWaitForSingleObject+0xc
0316ed3c 76432c02 KERNELBASE!WaitForSingleObjectEx+0x99
0316ed50 765b9839 KERNELBASE!WaitForSingleObject+0x12
(Inline) -------- combase!MTAThreadWaitForCall+0x43
0316ed80 7665d524 combase!MTAThreadDispatchCrossApartmentCall+0x1ed
(Inline) -------- combase!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x33a2
0316eed4 7653caea combase!CRpcChannelBuffer::SendReceive2+0×62d
(Inline) ——– combase!ClientCallRetryContext::SendReceiveWithRetry+0×2e
(Inline) ——– combase!CAptRpcChnl::SendReceiveInRetryContext+0×81
0316ef34 76581789 combase!DefaultSendReceive+0×9e
(Inline) ——– combase!CAptRpcChnl::SendReceive+0×38
0316ef98 7665a010 combase!CCtxComChnl::SendReceive+0×248
0316efbc 76f85769 combase!NdrExtpProxySendReceive+0×5c
0316efd4 77006c1b rpcrt4!NdrpProxySendReceive+0×29
0316f400 76659e1e rpcrt4!NdrClientCall2+0×22b
0316f420 7653c46f combase!ObjectStublessClient+0×6c
0316f430 76581c07 combase!ObjectStubless+0xf
0316f4c4 76583024 combase!CObjectContext::InternalContextCallback+0×1e4
0316f518 6e6fcd4b combase!CObjectContext::ContextCallback+0xbc
0316f564 6e6fd936 mscorwks!CtxEntry::EnterContextOle32BugAware+0×2b
0316f684 6e7329cf mscorwks!CtxEntry::EnterContext+0×325
0316f6b8 6e732a74 mscorwks!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xc4
0316f708 6e5908e3 mscorwks!RCWCleanupList::CleanupAllWrappers+0xdb
0316f74c 6e5907f3 mscorwks!SyncBlockCache::CleanupSyncBlocks+0xec
0316f910 6e589b7c mscorwks!Thread::DoExtraWorkForFinalizer+0×40
0316f920 6e54547f mscorwks!WKS::GCHeap::FinalizerThreadWorker+0×9a
0316f934 6e54541b mscorwks!Thread::DoADCallBack+0×32a
0316f9c8 6e54533a mscorwks!Thread::ShouldChangeAbortToUnload+0xe3
0316fa04 6e5b2763 mscorwks!Thread::ShouldChangeAbortToUnload+0×30a
0316fa2c 6e5b2774 mscorwks!ManagedThreadBase_NoADTransition+0×32
0316fa3c 6e5cb816 mscorwks!ManagedThreadBase::FinalizerBase+0xd
0316fa74 6e660ae9 mscorwks!WKS::GCHeap::FinalizerThreadStart+0xbb
0316fb10 76307c04 mscorwks!Thread::intermediateThreadProc+0×49
0316fb24 773fad1f kernel32!BaseThreadInitThunk+0×24
0316fb6c 773facea ntdll!__RtlUserThreadStart+0×2f
0316fb7c 00000000 ntdll!_RtlUserThreadStart+0×1b

We saw that it was blocked in an RPC call. Using the technique from In Search of Lost CID article we found the destination thread:

0:002> kvL
ChildEBP RetAddr  Args to Child
0316ecc8 76432cc7 0000096c 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0316ed3c 76432c02 0000096c ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0x99
0316ed50 765b9839 0000096c ffffffff 00ddfb88 KERNELBASE!WaitForSingleObject+0x12
(Inline) -------- -------- -------- -------- combase!MTAThreadWaitForCall+0x43
0316ed80 7665d524 00ddf298 0629fa10 0316efec combase!MTAThreadDispatchCrossApartmentCall+0x1ed
(Inline) -------- -------- -------- -------- combase!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x33a2
0316eed4 7653caea 00ddfb88 0316efec 0316efb4 combase!CRpcChannelBuffer::SendReceive2+0×62d
(Inline) ——– ——– ——– ——– combase!ClientCallRetryContext::SendReceiveWithRetry+0×2e
(Inline) ——– ——– ——– ——– combase!CAptRpcChnl::SendReceiveInRetryContext+0×81
0316ef34 76581789 00ddfb88 0316efec 0316efb4 combase!DefaultSendReceive+0×9e
(Inline) ——– ——– ——– ——– combase!CAptRpcChnl::SendReceive+0×38
0316ef98 7665a010 00ddfb88 0316efec 0316efb4 combase!CCtxComChnl::SendReceive+0×248
0316efbc 76f85769 0628365c 0316f018 76f85740 combase!NdrExtpProxySendReceive+0×5c
0316efd4 77006c1b 6d6b47ca 0628365c 0316f438 rpcrt4!NdrpProxySendReceive+0×29
0316f400 76659e1e 7652d8f8 76532ff0 0316f438 rpcrt4!NdrClientCall2+0×22b
[…]

0:002> dpp 00ddfb88
00ddfb88  7652d400 7665bff0 combase!CRpcChannelBuffer::QueryInterface
00ddfb8c  76541e2c 76664690 combase![thunk]:CRpcChannelBuffer::QueryInterface`adjustor{4}’
00ddfb90  7653a65c 766646a0 combase![thunk]:CRpcChannelBuffer::QueryInterface`adjustor{8}’
00ddfb94  adb1682c
00ddfb98  429b3908
00ddfb9c  2b59b182
00ddfba0  e6a936e1
00ddfba4  00000003
00ddfba8  0000002a
00ddfbac  06268d68 00000000
00ddfbb0  00000000
00ddfbb4  00ddf298 00ddf330
00ddfbb8  00ddfe70 00000000
00ddfbbc  062d7660 00000044
00ddfbc0  00deb5f0 7652d280 combase!CStdIdentity::`vftable’
00ddfbc4  7652b2e0 76568760 combase!CDestObject::QueryInterface
00ddfbc8  00070005
00ddfbcc  00000003
00ddfbd0  000060b0
00ddfbd4  00000000
00ddfbd8  00000000
00ddfbdc  7652d400 7665bff0 combase!CRpcChannelBuffer::QueryInterface
00ddfbe0  76541e2c 76664690 combase![thunk]:CRpcChannelBuffer::QueryInterface`adjustor{4}’
00ddfbe4  7653a65c 766646a0 combase![thunk]:CRpcChannelBuffer::QueryInterface`adjustor{8}’
00ddfbe8  adb1682c
00ddfbec  429b3908

0:002> dd 00ddf298
00ddf298  00ddf330 7666ddd0 000070b8 000060b0
00ddf2a8  056aadfb 14bb2b53 a45b843e 2611fcc9
00ddf2b8  a45b843e 2611fcc9 00001800 60b070b8
00ddf2c8  66fb7794 88242aca 04000203 00020052
00ddf2d8  00dbfb20 00000000 00000000 00000000
00ddf2e8  00000001 ffffffff 00de5e48 0628365c
00ddf2f8  00000005 00000000 00000001 00000000
00ddf308  00000000 00070005 00000000 00000000

We saw that the finalizer thread #2 was waiting for the thread #0 that was waiting for the finalizer thread #2:

0:002> ~
#  0  Id: 70b8.60b0 Suspend: 0 Teb: 7ecaf000 Unfrozen
1  Id: 70b8.26e8 Suspend: 0 Teb: 7ecac000 Unfrozen
.  2  Id: 70b8.5d2c Suspend: 0 Teb: 7eca9000 Unfrozen
3  Id: 70b8.551c Suspend: 0 Teb: 7eb76000 Unfrozen
4  Id: 70b8.7194 Suspend: 0 Teb: 7eb73000 Unfrozen
5  Id: 70b8.465c Suspend: 0 Teb: 7eb0f000 Unfrozen
6  Id: 70b8.64ac Suspend: 0 Teb: 7eb0c000 Unfrozen
7  Id: 70b8.6200 Suspend: 0 Teb: 7eb09000 Unfrozen
8  Id: 70b8.5790 Suspend: 0 Teb: 7eafa000 Unfrozen
9  Id: 70b8.6c3c Suspend: 0 Teb: 7eaf4000 Unfrozen
10  Id: 70b8.7320 Suspend: 0 Teb: 7eaeb000 Unfrozen
11  Id: 70b8.1ebc Suspend: 0 Teb: 7eb06000 Unfrozen
12  Id: 70b8.459c Suspend: 0 Teb: 7eb00000 Unfrozen
13  Id: 70b8.74e8 Suspend: 0 Teb: 7eb7f000 Unfrozen
14  Id: 70b8.6758 Suspend: 0 Teb: 7eafd000 Unfrozen
15  Id: 70b8.72e8 Suspend: 0 Teb: 7eaf1000 Unfrozen
16  Id: 70b8.5eec Suspend: 0 Teb: 7eaee000 Unfrozen
17  Id: 70b8.4a74 Suspend: 0 Teb: 7e83f000 Unfrozen
18  Id: 70b8.61b0 Suspend: 0 Teb: 7e83c000 Unfrozen
19  Id: 70b8.3cc4 Suspend: 0 Teb: 7e839000 Unfrozen
20  Id: 70b8.6554 Suspend: 0 Teb: 7e836000 Unfrozen
21  Id: 70b8.5b5c Suspend: 0 Teb: 7e833000 Unfrozen
22  Id: 70b8.6c48 Suspend: 0 Teb: 7e7ff000 Unfrozen
23  Id: 70b8.12dc Suspend: 0 Teb: 7e7fc000 Unfrozen
24  Id: 70b8.3a98 Suspend: 0 Teb: 7e7f9000 Unfrozen
25  Id: 70b8.1cb4 Suspend: 0 Teb: 7e7f6000 Unfrozen
26  Id: 70b8.5df8 Suspend: 0 Teb: 7e7f3000 Unfrozen
27  Id: 70b8.287c Suspend: 0 Teb: 7e69f000 Unfrozen
28  Id: 70b8.69b4 Suspend: 0 Teb: 7e69c000 Unfrozen
29  Id: 70b8.159c Suspend: 0 Teb: 7e699000 Unfrozen
30  Id: 70b8.1678 Suspend: 0 Teb: 7e696000 Unfrozen
31  Id: 70b8.8a0 Suspend: 0 Teb: 7e693000 Unfrozen
32  Id: 70b8.5984 Suspend: 0 Teb: 7e64f000 Unfrozen
33  Id: 70b8.256c Suspend: 0 Teb: 7e649000 Unfrozen

This is a variant of Deadlock memory analysis pattern.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Leave a Reply