Archive for May, 2017

Trace Analysis Patterns (Part 150)

Monday, May 22nd, 2017

Sometimes we are interested in Message Set that has the same time attribute value (or rounded to some digit). We call this analysis pattern Activity Packet by analogy with wave packets. It may allow identification of related threads and activities.

It is different from Activity Quantum analysis pattern where time attribute value may change for continuous Message Set with the same thread id.

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

Crash Dump Analysis Patterns (Part 252)

Sunday, May 21st, 2017

Some Stack Traces reveal a functional purpose, for example, painting, querying a database, doing HTML or JavaScript processing, loading a file, printing, or something else. Such traces from various Stack Trace Collections (unmanaged, managed, predicate, CPUs) may be compared for similarity and help with analysis patterns, such as examples in Wait Chain (C++11 condition variable, SRW lock), finding semantically Coupled Processes, and many others where we look at the meaning of stack trace frame sequences to relate them to each other. We call this analysis pattern Stack Trace Motif by analogy with Motif trace and log analysis pattern. Longer stack traces may contain several Motives and also Technology-Specific Subtraces (for example, COM interface invocation frames).

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

Crash Dump Analysis Patterns (Part 42o)

Saturday, May 20th, 2017

Slim Reader/Writer locks are available from Windows Vista and sometimes we can see them in Stack Trace Collection. Although, at the time of this writing, there is no WinDbg support for them, the techniques described in the example for C++11 condition variable Wait Chain analysis pattern can be used. Here is an example where we used semantics of stack trace similarity such as “rendering” to find the stack trace of the possible owner thread:

0:000> ~*k

[...]

4  Id: be4.2af4 Suspend: 0 Teb: 7efa1000 Unfrozen
# ChildEBP RetAddr
00 0414bfe8 776e2157 ntdll_77670000!NtWaitForKeyedEvent+0×15
01 0414c054 5c9c3f8e ntdll_77670000!RtlAcquireSRWLockExclusive+0×12e

02 0414c06c 5ca2ad83 mshtml!TSmartResource<CDXRenderLock>::Acquire<enum DXLock::Type>+0×5e
03 0414c09c 5cdffa63 mshtml!CDXSystem::CheckAndHandleDeviceReset+0×43
04 0414c0b0 5cdff9eb mshtml!CDoc::CheckAndHandleDeviceReset+0×23
05 0414c130 5cabe82e mshtml!CDoc::OnPaint+0xcb
06 0414c164 5c9d632b mshtml!CServer::OnWindowMessage+0xfb
07 0414c324 5c9bbcb0 mshtml!CDoc::OnWindowMessage+0×24c
08 0414c354 76ea62fa mshtml!CServer::WndProc+0×58
09 0414c380 76ea731e user32!InternalCallWinProc+0×23
0a 0414c3f8 76ea6ded user32!UserCallWinProcCheckWow+0xd8
0b 0414c458 76ea6e4c user32!DispatchClientMessage+0xec
0c 0414c494 7768011a user32!__fnDWORD+0×2b
0d 0414c4cc 76eb1342 ntdll_77670000!KiUserCallbackDispatcher+0×2e
0e 0414c514 76ea789a user32!DispatchMessageWorker+0×442
0f 0414c524 5f69a97c user32!DispatchMessageW+0xf
10 0414f6f4 5f6dc648 ieframe!CTabWindow::_TabWindowThreadProc+0×464
11 0414f7b4 7543dbfc ieframe!LCIETab_ThreadProc+0×3e7
12 0414f7cc 6b303a31 iertutil!_IsoThreadProc_WrapperToReleaseScope+0×1c
13 0414f804 7696338a IEShims!NS_CreateThread::DesktopIE_ThreadProc+0×94
14 0414f810 776a9902 kernel32!BaseThreadInitThunk+0xe
15 0414f850 776a98d5 ntdll_77670000!__RtlUserThreadStart+0×70
16 0414f868 00000000 ntdll_77670000!_RtlUserThreadStart+0×1b

[...]

23  Id: be4.b88 Suspend: 0 Teb: 7ef4a000 Unfrozen
# ChildEBP RetAddr
00 0f3cbb60 76a815ce ntdll_77670000!NtWaitForSingleObject+0x15
01 0f3cbbcc 76961194 KERNELBASE!WaitForSingleObjectEx+0x98
02 0f3cbbe4 76961148 kernel32!WaitForSingleObjectExImplementation+0x75
03 0f3cbbf8 746a5aa5 kernel32!WaitForSingleObject+0x12
04 0f3cbcac 6aef2f6c dwmapi!DwmpDxGetWindowSharedSurface+0x374
05 0f3cc198 6aef1c2e dxgi!CDXGISwapChain::PresentImpl+0x6fa
06 0f3cc1f0 5d59339f dxgi!CDXGISwapChain::Present+0x5d
07 0f3cc214 5cea42bc mshtml!CDXSwapChainTargetSurface::OnPresent+0x2f
08 0f3cc240 5cea360d mshtml!CDXRenderTarget::Present+0×5c
09 0f3cc5c4 5cdbf5e1 mshtml!CPaintHandler::RenderInternal+0xad3
0a 0f3cc5f0 5ca1da8e mshtml!CPaintController::Render+0×39
0b 0f3cc630 5ce8692b mshtml!CRenderTaskDrawInPlace::Execute+0xc1
0c 0f3cc66c 5ca1c4c9 mshtml!CRenderTaskQueue::AddRenderTask+0xd2
0d 0f3cc6e0 5ca1a466 mshtml!CView::RenderInPlace+0×3cd
0e 0f3cc718 5ca1a4d4 mshtml!CDoc::PaintWorker+0×24d
0f 0f3cc738 5ca2983b mshtml!CDoc::PaintInPlace+0×40
10 0f3cc76c 5ca2978a mshtml!CPaintController::RunRenderingLoop+0×68

11 0f3cc790 5ca1180c mshtml!CPaintController::OnUpdateBeat+0×66
12 0f3cc7cc 5ca2a7af mshtml!CPaintBeat::OnBeat+0×234
13 0f3cc7f8 5c9bd27b mshtml!CPaintBeat::OnVSyncMethodCall+0×86
14 0f3cc840 5c9bc99c mshtml!GlobalWndOnMethodCall+0×17b
15 0f3cc894 76ea62fa mshtml!GlobalWndProc+0×103
16 0f3cc8c0 76ea6d3a user32!InternalCallWinProc+0×23
17 0f3cc938 76ea77d3 user32!UserCallWinProcCheckWow+0×109
18 0f3cc99c 76ea789a user32!DispatchMessageWorker+0×3cb
19 0f3cc9ac 5f69a97c user32!DispatchMessageW+0xf
1a 0f3cfb7c 5f6dc648 ieframe!CTabWindow::_TabWindowThreadProc+0×464
1b 0f3cfc3c 7543dbfc ieframe!LCIETab_ThreadProc+0×3e7
1c 0f3cfc54 6b303a31 iertutil!_IsoThreadProc_WrapperToReleaseScope+0×1c
1d 0f3cfc8c 7696338a IEShims!NS_CreateThread::DesktopIE_ThreadProc+0×94
1e 0f3cfc98 776a9902 kernel32!BaseThreadInitThunk+0xe
1f 0f3cfcd8 776a98d5 ntdll_77670000!__RtlUserThreadStart+0×70
20 0f3cfcf0 00000000 ntdll_77670000!_RtlUserThreadStart+0×1b

[...]

28  Id: be4.17c8 Suspend: 0 Teb: 7ef3d000 Unfrozen
# ChildEBP RetAddr
00 0ee2c988 776e2157 ntdll_77670000!NtWaitForKeyedEvent+0×15
01 0ee2c9f4 5c9c3f8e ntdll_77670000!RtlAcquireSRWLockExclusive+0×12e

02 0ee2ca0c 5cc69e25 mshtml!TSmartResource<CDXRenderLock>::Acquire<enum DXLock::Type>+0×5e
03 0ee2ca3c 5cc71743 mshtml!CDXSystemShared::PurgeResourceCaches+0×29
04 0ee2ca50 5cc7170d mshtml!CDXSystem::~CDXSystem+0×1d
05 0ee2ca5c 5cc716e6 mshtml!RefCounted<CDXSystem,SingleThreadedRefCount>::`vector deleting destructor’+0xd
06 0ee2ca6c 5c9bea0d mshtml!RefCounted<CDXSystem,SingleThreadedRefCount>::Release+0×2d
07 0ee2ca7c 5cc6a734 mshtml!TSmartPointer<Windows::Foundation::IAsyncOperation<Windows::Foundation:: Collections::IMapView<HSTRING__ *,Windows::Storage::Streams::RandomAccessStreamReference *> *> >::~TSmartPointer<Windows::Foundation::IAsyncOperation<Windows::Foundation:: Collections::IMapView<HSTRING__ *,Windows::Storage::Streams::RandomAccessStreamReference *> *> >+0×1d
08 0ee2ca84 5cc6a6e0 mshtml!DeinitRenderSystem+0×14
09 0ee2caa0 5cc6a63a mshtml!DeinitThreadStateStruct<void (__stdcall*)(EXTENDEDTHREADSTATE *),EXTENDEDTHREADSTATE>+0×22
0a 0ee2cab0 5d272f1d mshtml!DeinitExtendedThreadState+0×24
0b 0ee2cacc 5cabd85e mshtml!_DecrementObjectCount+0×79
0c 0ee2cad8 5f78b662 mshtml!CBaseLockCF::LockServer+0×4a
0d 0ee2cafc 5f797c4d ieframe!CBaseBrowser2::~CBaseBrowser2+0×265
0e 0ee2cb08 5f797c2e ieframe!CShellBrowser2::`vector deleting destructor’+0xd
0f 0ee2cb24 5f78e7bf ieframe!CShellBrowser2::Release+0×47
10 0ee2fcf4 5f6dc648 ieframe!CTabWindow::_TabWindowThreadProc+0×83e
11 0ee2fdb4 7543dbfc ieframe!LCIETab_ThreadProc+0×3e7
12 0ee2fdcc 6b303a31 iertutil!_IsoThreadProc_WrapperToReleaseScope+0×1c
13 0ee2fe04 7696338a IEShims!NS_CreateThread::DesktopIE_ThreadProc+0×94
14 0ee2fe10 776a9902 kernel32!BaseThreadInitThunk+0xe
15 0ee2fe50 776a98d5 ntdll_77670000!__RtlUserThreadStart+0×70
16 0ee2fe68 00000000 ntdll_77670000!_RtlUserThreadStart+0×1b

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

Trace Analysis Patterns (Part 149)

Thursday, May 18th, 2017

A typical software trace or log (for example, from Process Monitor) lists messages from several processes and threads sequentially. However, such columns may be split into individual process ID or thread ID columns. The same can be done for any Adjoint Thread and illustrated in the following diagram:

We call this analysis pattern Combed Trace by analogy with multibraiding.

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

Trace Analysis Patterns (Part 148)

Wednesday, May 17th, 2017

In order to perform Inter-Correlational analysis among traces and logs especially when we have Indexical Trace we need a dual operation: an ability to identify traces and Use Case Trails, and, if necessary, find their corresponding Braids of Activity in an index trace. Some data from the tracing domain or use case description may serve is Intrinsic ID. It can be itself some numeric ID, user or computer name.

A typical log analysis case from a distributed environment is illustrated on the following diagram:

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

Crash Dump Analysis Patterns (Part 117b)

Sunday, May 14th, 2017

This is another variant of Invalid Parameter pattern where an invalid parameter is passed to either statically or dynamically linked C runtime function. Exception codes may vary, for example, c000000d and c0000417 as the following examples illustrate:

0:000> k
Child-SP          RetAddr           Call Site
00000000`0289e858 00007ff8`cf4f13ed ntdll!NtWaitForMultipleObjects+0xa
00000000`0289e860 00007ff8`d1157d51 KERNELBASE!WaitForMultipleObjectsEx+0xe1
00000000`0289eb40 00007ff8`d1157773 kernel32!WerpReportFaultInternal+0x581
00000000`0289f0b0 00007ff8`cf5d1cdf kernel32!WerpReportFault+0x83
00000000`0289f0e0 00007ff6`f0225095 KERNELBASE!UnhandledExceptionFilter+0×23f
00000000`0289f1d0 00007ff6`f021ec89 ModuleA!_invalid_parameter+0xc5
00000000`0289f790 00007ff6`f01a2636 ModuleA!vswprintf_s+0×79

[…]
00000000`0289fdc0 00007ff8`d20b5454 kernel32!BaseThreadInitThunk+0×22
00000000`0289fdf0 00000000`00000000 ntdll!RtlUserThreadStart+0×34

0:000> !analyze -v
[...]
EXCEPTION_RECORD:  ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 00007ff6f021ec89 (ModuleA!vswprintf_s+0x0000000000000079)
ExceptionCode: c000000d
ExceptionFlags: 00000000
NumberParameters: 0
[…]
EXCEPTION_CODE: (NTSTATUS) 0xc000000d - An invalid parameter was passed to a service or function.

0:000> k
# ChildEBP RetAddr
00 002e6de8 74a01606 ntdll!NtWaitForMultipleObjects+0xc
01 002e6f7c 74a014b8 KERNELBASE!WaitForMultipleObjectsEx+0x136
02 002e6f98 7431a02a KERNELBASE!WaitForMultipleObjects+0x18
03 002e73d4 74319ac6 kernel32!WerpReportFaultInternal+0x545
04 002e73e4 742fcf09 kernel32!WerpReportFault+0x7a
05 002e73ec 74a1a013 kernel32!BasepReportFault+0x19
06 002e7480 73edcc2c KERNELBASE!UnhandledExceptionFilter+0×1b3
07 002e77b8 73ea75b4 msvcr90!_invoke_watson+0xf9
08 002e77e0 5f29a294 msvcr90!wcsncpy_s+0×41

09 002e77fc 5f434563 ModuleB+0×6a294
[…]
44 002efda8 76f19e54 kernel32!BaseThreadInitThunk+0×24
45 002efdf0 76f19e1f ntdll!__RtlUserThreadStart+0×2f
46 002efe00 00000000 ntdll!_RtlUserThreadStart+0×1b

0:000> !analyze -v
[...]
EXCEPTION_RECORD:  (.exr -1)
ExceptionAddress: 73ea75b4 (msvcr90!wcsncpy_s+0x00000041)
ExceptionCode: c0000417
ExceptionFlags: 00000001
NumberParameters: 0
[…]
EXCEPTION_CODE: (NTSTATUS) 0xc0000417 - An invalid parameter was passed to a C runtime function.

We can inspect parameters passed to the function where it is possible. In 32-bit memory dumps we may see the first 3 parameters in the output of kv WinDbg command. More than 3 function parameters require the analysis of the raw stack region. 64-bit memory dumps may require disassembled code analysis of the caller (via ub WinDbg command).

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

Crash Dump Analysis Patterns (Part 9h)

Saturday, May 13th, 2017

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 -

Crash Dump Analysis Patterns (Part 251)

Friday, May 12th, 2017

When the same API function is executed it may leave the same data structure in its Execution Residue inside raw stack regions of different threads. We call this analysis pattern Frame Regularity. It may be used to find and correctly interpret stack frame values from thread stack traces or regions based on values found in some other thread stack trace or region where we already know their meaning.

Consider the critical section Wait Chain below. We want to know what critical section the thread F34 is waiting for. The backwards disassembly of 00007ffd`41894e14 return address doesn’t show the critical section address explicitly. However, 00007ffd`43827e40 return address disassembly from a different critical section thread owner D7C shows critical section address 00007ffd`4391d8a8 which we can find as a 3rd “argument” to ntdll!RtlpWaitOnCriticalSection (which is just a value picked up from the stack region and not the real function argument passed by stack). Using Frame Regularity we try to see if the 3rd value for the same function from the thread F34 under question is also a critical section address 00000071`3f08c488. Indeed, we find that it is the address of the critical section owned by the thread B18.

0:000> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x00007ffd4391dbe8
Critical section   = 0x00007ffd4391d8a8 (ntdll!LdrpLoaderLock+0x0)
LOCKED
LockCount          = 0x13
WaiterWoken        = No
OwningThread       = 0×0000000000000f34
RecursionCount     = 0×1
LockSemaphore      = 0×8B0
SpinCount          = 0×0000000004000000
OwningThread DbgId = ~14s
OwningThread Stack =
Child-SP          RetAddr           : Args to Child                                                           : Call Site
00000071`40d4c618 00007ffd`43829a85 : 00000071`3f08c488 00000000`00000002 00000000`bd000200 00000000`00000000 : ntdll!NtWaitForSingleObject+0xa
00000071`40d4c620 00007ffd`43827f44 : 00000000`a90002ab 00007ffd`40d52eba 00000071`3f08c488 00000000`00000000 : ntdll!RtlpWaitOnCriticalSection+0xe1
00000071`40d4c6f0 00007ffd`41894e14 : 00000071`3f08c488 00007ffd`4229b3a8 00000000`00000000 00000071`3f08c470 : ntdll!RtlpEnterCriticalSectionContended+0xa4
00000071`40d4c730 00007ffd`41895d8d : 00000071`40c52ab0 00000000`00000000 00230022`00210020 00270026`00250024 : shell32!kfapi::CFolderPathResolver::GetPath+0×168
00000071`40d4dd50 00007ffd`41892d50 : 00000000`00000080 00000000`000000ce 00000000`00000104 00000000`000003ff : shell32!kfapi::CFolderCache::GetPath+0×772
00000071`40d4e0c0 00007ffd`41893540 : 00000071`40d4e258 00000000`20000020 00000000`000000ce 00000071`42141080 : shell32!kfapi::CKFFacade::GetFolderPath+0×120
00000071`40d4e220 00007ffd`4189368c : 00000000`00008023 00000000`000000ce 00000000`5307cc38 00000000`000000ce : shell32!SHGetFolderPathEx+0×80
00000071`40d4e290 00007ffd`40d61939 : 00000000`00000000 00000000`00000000 00000000`00000037 00000000`00008023 : shell32!SHGetFolderPathWWorker+0xf9
00000071`40d4e2f0 00007ffd`41a80fba : 00000000`00000000 00000000`00000000 00000071`40d4e400 00000071`42010000 : KERNELBASE!SHGetFolderPathW+0×49
00000071`40d4e330 00007ffd`40d7e60f : 00000071`00000001 00000000`00000020 00000000`00000035 00000071`42141080 : shell32!SHGetSpecialFolderPathWWorker+0×23
00000071`40d4e370 00000000`5317704d : 00000071`40d4e7d0 00000071`40d4ee68 00000000`00000000 00000000`53062b30 : KERNELBASE!SHGetSpecialFolderPathW+0×3f
00000071`40d4e3a0 00000000`530e72f1 : 00000000`5333fa10 00000000`00000001 00000000`5333fa10 00000000`530ab470 : ModuleA+0xccded
[…]
00000071`40d4eba0 00007ffd`4380e82e : 00000071`40cc6780 00000000`53060000 00000071`00000001 00007ffd`40892421 : ntdll!LdrpCallInitRoutine+0×4c
00000071`40d4ec00 00007ffd`4380e624 : 00000071`40cb2790 00007ffd`4384ee00 00000071`40cb2790 00000000`53224dec : ntdll!LdrpInitializeNode+0×176
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
—————————————–
DebugInfo          = 0×0000007140c52a70
Critical section   = 0×00007ffd31f41a88 (localspl!g_csBidiAccess+0×8)
LOCKED
LockCount          = 0×4
WaiterWoken        = No
OwningThread       = 0×0000000000000d7c
RecursionCount     = 0×1
LockSemaphore      = 0×1410
SpinCount          = 0×00000000020007d0
OwningThread DbgId = ~7s
OwningThread Stack =
Child-SP          RetAddr           : Args to Child                                                           : Call Site
00000071`4029e708 00007ffd`43829a85 : 0000a498`9a4b3f83 00000071`4029ec00 00000071`4029e880 00000071`4029e858 : ntdll!NtWaitForSingleObject+0xa
00000071`4029e710 00007ffd`43827f44 : 00000000`00000002 00007ffd`00000000 00007ffd`4391d8a8 00000071`4029e9d0 : ntdll!RtlpWaitOnCriticalSection+0xe1
00000071`4029e7e0 00007ffd`43827e40 : 00007ffd`41613750 00000071`3efa2a10 00007ffd`416b4d58 00007ffd`41686000 : ntdll!RtlpEnterCriticalSectionContended+0xa4
00000071`4029e820 00007ffd`4380ad5a : 00007ffd`41686000 00000071`4029e8e0 00007ffd`41613750 00000071`4029eeb8 : ntdll!LdrpAcquireLoaderLock+0×2c
00000071`4029e860 00007ffd`4386785f : 00000000`00000000 00007ffd`41685c64 00000000`00000000 00000071`4029e980 : ntdll!LdrpGetDelayloadExportDll+0×7e
00000071`4029e920 00007ffd`43826c8e : 00000000`00000000 00007ffd`41685c64 00000000`00000000 00007ffd`41613750 : ntdll!LdrpHandleProtectedDelayload+0×3f
00000071`4029ede0 00007ffd`4153763b : 00000071`4029ef50 00000000`00000000 00007ffd`2f4d3be0 00000000`00000003 : ntdll!LdrResolveDelayLoadedAPI+0×8e
00000071`4029ee40 00007ffd`415376df : 00000071`3ffe3020 00007ffd`2f4d2482 00000071`3ffe3020 00000071`3ffcb078 : combase!__delayLoadHelper2+0×2b
00000071`4029ee80 00007ffd`415239b6 : a4e9da62`d9130000 00000071`4029eed0 00000000`00000000 00000000`0000006c : combase!_tailMerge_OLEAUT32_dll+0×3f
00000071`4029eef0 00007ffd`41523883 : 00000071`40c22230 00000071`4029f029 00000000`80070015 00000071`3ffcf598 : combase!wCoUninitialize+0xb6
00000071`4029ef20 00007ffd`31e74e1a : 00000071`40c22230 00000000`00000000 00000000`80070015 00007ffd`2f4d3be0 : combase!CoUninitialize+0xb3
00000071`4029ef50 00007ffd`31e7459c : 00000000`00000000 00000071`4029f1d8 00007ffd`31f416d8 00000000`00000001 : localspl!GetBidiStrings+0×3be
00000071`4029f090 00007ffd`31e72150 : 00000000`00000000 00000071`4029f240 00007ffd`31f416d8 00000000`00000000 : localspl!GetBidiPropertiesForDevnode+0×9c
00000071`4029f140 00007ffd`31e7b03b : 00000000`00000008 00000071`403588e0 00000071`40a83130 00000000`00000001 : localspl!GetPropertiesFromPrinter+0×1f4
00000071`4029f750 00007ffd`31e7ae90 : 00000071`40aa6e40 00000000`00000000 00000000`00000001 00007ffd`ffff4b5e : localspl!CreatePrintQueueDevnodeWorker+0xab
00000071`4029f8a0 00007ffd`31eb475e : 00000000`00000000 00000000`00000000 00000071`3f05f470 00000000`00000000 : localspl!CreatePrintQueueDevnode+0xb4
00000071`4029f920 00007ffd`31eb46eb : 00000071`3ffe35c0 00000071`3f05f470 00007ffd`31eb4710 00000000`00000000 : localspl!DevnodeCreationWorkItem::Run+0×4e
00000071`4029f990 00007ffd`4386247e : 00007ffd`31eb46b0 00000071`3f05f3c0 00000071`4029fb78 00000071`3f05f470 : localspl!NThreadingLibrary::TWorkCrew::tpSimpleCallback+0×3b
00000071`4029f9c0 00007ffd`43824a5d : 00000071`3f05f470 00000071`3efd23f0 00000000`00000000 00000071`3f01e3e8 : ntdll!TppSimplepExecuteCallback+0×7e
00000071`4029fa00 00007ffd`410313d2 : 00000000`00000000 00007ffd`438245e0 00000071`3f01bf10 00000000`00000000 : ntdll!TppWorkerThread+0×47d
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
—————————————–
DebugInfo          = 0×0000007140c52970
Critical section   = 0×0000000001017600 (ModuleB+0×38F80)
LOCKED
LockCount          = 0×1
WaiterWoken        = No
OwningThread       = 0×0000000000000fe8
RecursionCount     = 0×1
LockSemaphore      = 0×14A0
SpinCount          = 0×00000000020007d0
OwningThread DbgId = ~22s
OwningThread Stack =
Child-SP          RetAddr           : Args to Child                                                           : Call Site
00000071`4102e6a8 00007ffd`43829a85 : 00000000`00000050 00007ffd`4381c937 00000071`3f110000 00000000`00000000 : ntdll!NtWaitForSingleObject+0xa
00000071`4102e6b0 00007ffd`43827f44 : 00000000`00000000 00000000`00000000 00007ffd`4391d8a8 00000000`00000000 : ntdll!RtlpWaitOnCriticalSection+0xe1
00000071`4102e780 00007ffd`43827e40 : 00000071`4102ebe8 00000000`00000000 00000071`4102ebb8 00000071`40cc5a00 : ntdll!RtlpEnterCriticalSectionContended+0xa4
00000071`4102e7c0 00007ffd`43818998 : 00007ff7`acadf000 00000071`4102e830 00000071`4102e830 00000071`4102e830 : ntdll!LdrpAcquireLoaderLock+0×2c
00000071`4102e800 00007ffd`4380b229 : 00000000`00000000 00000071`4102ee40 00007ffd`437f4d38 00000000`00000000 : ntdll!LdrpFindOrMapDll+0×4f8
00000071`4102eb50 00007ffd`4380af29 : 00000000`00000000 00000000`00000000 00000071`4102ee40 00000071`4102ee40 : ntdll!LdrpLoadDll+0×295
00000071`4102ed80 00007ffd`40d58e4a : 00000000`00000000 00000071`4102ee50 00000000`010154a0 00000000`00000002 : ntdll!LdrLoadDll+0×99
00000071`4102ee00 00000000`00fd36ec : 00000000`00000000 00000000`010020a0 00000000`010154a0 00000000`00000000 : KERNELBASE!LoadLibraryExW+0xca
00000071`4102ee70 00000000`00fd3aa6 : 00000071`41147420 00000000`028424c0 00000000`00000001 00000071`411473dc : ModuleB+0×1f1c
[…]
00000071`4102f5b0 00007ffd`3a9b5804 : 00000071`40c33ea8 00007ff7`00000008 00000000`00000008 00000071`3ffff190 : winspool!SpoolerPrinterEventNative+0xb1
00000071`4102f620 00007ffd`31a5566d : 00000071`40c33ea8 00000071`4102f719 00000000`00000008 00000000`00000000 : winspool!SpoolerPrinterEvent+0×54
00000071`4102f660 00007ffd`31e76682 : 00007ffd`31a55480 00000071`40c33ea8 00000071`4102f7c0 00000071`40aabcc0 : PrintIsolationProxy!sandbox::PrintSandboxObject::SandboxDriverEvent+0×1ed
00000071`4102f760 00007ffd`31e7659a : 00000071`3ffaf750 00007ffd`31e76610 00000071`40aabcc0 00000000`00000008 : localspl!sandbox::SandboxObserver::SandboxDriverEvent+0×72
00000071`4102f7b0 00007ffd`31e7621b : 00000071`40c33ea8 00000000`00000000 00000071`40c33ea8 00000000`00000000 : localspl!sandbox::SandboxPrinterDriverEvent+0xda
00000071`4102f820 00007ffd`31e76169 : 00000071`40aa6e40 00000000`00000001 00000000`00000000 00007ffd`31f40001 : localspl!SplDriverEvent+0×5b
00000071`4102f890 00007ffd`31f11c4b : 00000000`00000000 00000071`4102f940 00000071`40aa6e40 00007ffd`31f400c8 : localspl!PrinterDriverEvent+0xbd
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
—————————————–
DebugInfo          = 0×0000007140c52630
Critical section   = 0×000000713f08c488 (+0×713F08C488)
LOCKED
LockCount          = 0×1
WaiterWoken        = No
OwningThread       = 0×0000000000000b18
RecursionCount     = 0×1
LockSemaphore      = 0×14AC
SpinCount          = 0×00000000020007d0
OwningThread DbgId = ~1s
OwningThread Stack =
Child-SP          RetAddr           : Args to Child                                                           : Call Site
00000071`3fe4b5e8 00007ffd`43829a85 : 00000001`00000000 00000000`00000000 00000071`41927fd0 00007ffd`43821067 : ntdll!NtWaitForSingleObject+0xa
00000071`3fe4b5f0 00007ffd`43827f44 : 00000000`00000000 00000000`0000017b 00007ffd`4391d8a8 00000000`00000000 : ntdll!RtlpWaitOnCriticalSection+0xe1
00000071`3fe4b6c0 00007ffd`43827e40 : 00007ffd`41c57850 00000071`3efe3700 00007ffd`4229bf90 00007ffd`42203380 : ntdll!RtlpEnterCriticalSectionContended+0xa4
00000071`3fe4b700 00007ffd`4380ad5a : 00007ffd`42203380 00000071`3fe4b7c0 00007ffd`41c57850 00007ffd`4381609c : ntdll!LdrpAcquireLoaderLock+0×2c
00000071`3fe4b740 00007ffd`4386785f : 00000000`00000000 00007ffd`422026f4 00000071`3ef01790 00000071`3fe4b860 : ntdll!LdrpGetDelayloadExportDll+0×7e
00000071`3fe4b800 00007ffd`43826c8e : 00000000`00000000 00007ffd`422026f4 00000000`00000000 00007ffd`41c57850 : ntdll!LdrpHandleProtectedDelayload+0×3f
00000071`3fe4bcc0 00007ffd`41a818eb : 00000071`3fe4c910 00000071`3fe4c8a0 00000000`00000000 ffffffff`ffffffff : ntdll!LdrResolveDelayLoadedAPI+0×8e
00000071`3fe4bd20 00007ffd`41896d9f : 00000071`40c52670 ffffffff`ffffffff 00000000`00000000 00000071`3fe4e201 : shell32!_delayLoadHelper2+0×2b
00000071`3fe4bd60 00007ffd`41894374 : 00000071`3fe4c8a0 00000071`3fe4bf10 00000000`00000027 00000071`3fe4bed0 : shell32!_tailMerge_api_ms_win_core_com_l1_1_1_dll+0×3f
00000071`3fe4bdd0 00007ffd`4189409a : 00000000`00000000 00000000`00000000 00000071`3fe4c910 00000000`00000000 : shell32!kfapi::CFolderDefinitionStorage::_LoadRegistry+0xb4
00000071`3fe4c440 00007ffd`41896943 : 00000000`00000031 00000000`00000000 00000071`3fe4c698 00000071`40c52670 : shell32!kfapi::CFolderDefinitionStorage::Load+0×66
00000071`3fe4c6a0 00007ffd`4189796a : 00000000`00000000 00000071`40c539a0 00000071`40c37700 00007ffd`41a80f90 : shell32!kfapi::CFolderPathResolver::GetPath+0×242
00000071`3fe4dcc0 00007ffd`41892d50 : 00000071`3fe4e050 00000071`3fe4e038 00000071`3fe4e038 00000000`00000200 : shell32!kfapi::CFolderCache::GetPath+0xb74
00000071`3fe4e030 00007ffd`41893540 : 00000071`3fe4e1c8 00000071`40cb16f0 00000071`40cb16f0 00000000`00000000 : shell32!kfapi::CKFFacade::GetFolderPath+0×120
00000071`3fe4e190 00007ffd`4189368c : 00000000`00008023 00007ffd`4382c0ae 00000000`00000000 00000071`3ef92bd0 : shell32!SHGetFolderPathEx+0×80
00000071`3fe4e200 00007ffd`40d61939 : 00000000`00000000 00000000`00000000 00007ffd`40dc3f80 00000000`00008023 : shell32!SHGetFolderPathWWorker+0xf9
00000071`3fe4e260 00007ffd`41a80fba : 00000000`00000000 00000000`00000000 00000071`3fe4e370 00000000`00000000 : KERNELBASE!SHGetFolderPathW+0×49
00000071`3fe4e2a0 00007ffd`40d7e60f : 00000000`00000000 00000071`3fe4e370 00000000`00000023 00000000`00000001 : shell32!SHGetSpecialFolderPathWWorker+0×23
00000071`3fe4e2e0 00000000`540b036d : 00000071`3fe4e630 00000000`00000001 00000000`00000000 00000071`3fe4e6b0 : KERNELBASE!SHGetSpecialFolderPathW+0×3f
00000071`3fe4e310 00000000`54096f45 : 00000071`3fe4e708 00000000`00000001 00000071`3fe4e6d8 00000000`53fd1903 : ModuleC+0xdca2d
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.

0:000> ub 00007ffd`41894e14
shell32!kfapi::CFolderPathResolver::GetPath+0×145:
00007ffd`41894df1 498d5d30        lea     rbx,[r13+30h]
00007ffd`41894df5 48895c2468      mov     qword ptr [rsp+68h],rbx
00007ffd`41894dfa 4c897c2470      mov     qword ptr [rsp+70h],r15
00007ffd`41894dff 498bff          mov     rdi,r15
00007ffd`41894e02 4c897c2470      mov     qword ptr [rsp+70h],r15
00007ffd`41894e07 488975e0        mov     qword ptr [rbp-20h],rsi
00007ffd`41894e0b 488bce          mov     rcx,rsi
00007ffd`41894e0e ff159cbaa900    call    qword ptr [shell32!_imp_EnterCriticalSection (00007ffd`423308b0)]

0:000> ub 00007ffd`43827e40
ntdll!LdrpAcquireLoaderLock:
00007ffd`43827e14 4053            push    rbx
00007ffd`43827e16 4883ec30        sub     rsp,30h
00007ffd`43827e1a 488d0d4f8d0f00  lea     rcx,[ntdll!LdrpModuleEnumLock (00007ffd`43920b70)]
00007ffd`43827e21 e8ca040000      call    ntdll!RtlAcquireSRWLockShared (00007ffd`438282f0)
00007ffd`43827e26 803c258403fe7f00 cmp     byte ptr [SharedUserData+0×384 (00000000`7ffe0384)],0
00007ffd`43827e2e 0f85242c0700    jne     ntdll!LdrpAcquireLoaderLock+0×72c44 (00007ffd`4389aa58)
00007ffd`43827e34 488d0d6d5a0f00  lea     rcx,[ntdll!LdrpLoaderLock (00007ffd`4391d8a8)]
00007ffd`43827e3b e820000000      call    ntdll!RtlEnterCriticalSection (00007ffd`43827e60)

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

Crash Dump Analysis Patterns (Part 29e)

Monday, May 8th, 2017

This is High Contention pattern variant for .NET heap where we can see gc_heap functions in unmanaged Stack Trace Collection, Spiking Threads doing garbage collection, and threads waiting for object allocation:

0:000> ~*k

[...]

4  Id: ad8.1338 Suspend: 0 Teb: 00007ff5`ff774000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`f9dff1c8 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`f9dff1d0 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`f9dff270 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`f9dff2b0 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`f9dff310 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`f9dff3a0 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`f9dff3d0 00007ff9`ee74073f clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`f9dff400 00007ff9`ee740cfd clr!SVR::GCHeap::GarbageCollect+0x2998df
08 00000030`f9dff440 00007ff9`ee4ccdf9 clr!SVR::WaitForFinalizerEvent+0x3272ed
09 00000030`f9dff480 00007ff9`ee35c481 clr!SVR::GCHeap::FinalizerThreadWorker+0x4a
0a 00000030`f9dff4c0 00007ff9`ee35c408 clr!ManagedThreadBase_DispatchInner+0x2d
0b 00000030`f9dff500 00007ff9`ee35c379 clr!ManagedThreadBase_DispatchMiddle+0x6c
0c 00000030`f9dff600 00007ff9`ee46c477 clr!ManagedThreadBase_DispatchOuter+0x75
0d 00000030`f9dff690 00007ff9`ee417de6 clr!SVR::GCHeap::FinalizerThreadStart+0xd7
0e 00000030`f9dff730 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0x7d
0f 00000030`f9dff7f0 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0x22
10 00000030`f9dff820 00000000`00000000 ntdll!RtlUserThreadStart+0x34

[...]

8  Id: ad8.1960 Suspend: 0 Teb: 00007ff5`ff58c000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`fb90b898 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`fb90b8a0 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`fb90b940 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`fb90b980 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`fb90b9e0 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`fb90ba70 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`fb90baa0 00007ff9`ee780417 clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`fb90bad0 00007ff9`ee4c41e8 clr!SVR::gc_heap::wait_for_bgc_high_memory+0x2b8907
08 00000030`fb90bb60 00007ff9`ee355272 clr!SVR::GCHeap::Alloc+0×257
09 00000030`fb90bbc0 00007ff9`eb524a1d clr!JIT_New+0×142

0a 00000030`fb90be70 00007ff9`e8bd8ec8 System_Xml_ni+0×154a1d
0b 00000030`fb90bed0 00007ff9`e8d6ec7c System_Runtime_Serialization_ni+0xa8ec8
0c 00000030`fb90bf20 00007ff9`e9ed637b System_Runtime_Serialization_ni+0×23ec7c
0d 00000030`fb90bf80 00007ff9`ea6df472 System_ServiceModel_ni+0xdd637b
0e 00000030`fb90bfe0 00000030`fb90bfc0 System_ServiceModel_ni+0×15df472
0f 00000030`fb90bfe8 00000000`00000000 0×00000030`fb90bfc0

[...]

14  Id: ad8.11d4 Suspend: 0 Teb: 00007ff5`ff586000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000031`4a42eb10 00007ff9`ee4a3a76 clr!SVR::gc_heap::background_mark_simple1+0xcd9
01 00000031`4a42eba0 00007ff9`ee4a458b clr!SVR::gc_heap::background_mark_simple+0×99
02 00000031`4a42ebd0 00007ff9`ee52e68c clr!SVR::gc_heap::background_promote+0×15d
03 00000031`4a42ec40 00007ff9`ee538836 clr!PinObject+0×2c
04 00000031`4a42ec80 00007ff9`ee532fc8 clr!ScanConsecutiveHandlesWithoutUserData+0×62
05 00000031`4a42ecb0 00007ff9`ee5338f2 clr!BlockScanBlocksWithoutUserData+0×44
06 00000031`4a42ece0 00007ff9`ee5339fc clr!ProcessScanQNode+0×3d
07 00000031`4a42ed10 00007ff9`ee53397d clr!ProcessScanQueue+0×3d
08 00000031`4a42ed40 00007ff9`ee533bcf clr!xxxTableScanQueuedBlocksAsync+0×5d
09 00000031`4a42ed70 00007ff9`ee5353a5 clr!xxxAsyncSegmentIterator+0×2d
0a 00000031`4a42eda0 00007ff9`ee533ab6 clr!TableScanHandles+0×79
0b 00000031`4a42ee50 00007ff9`ee535607 clr!xxxTableScanHandlesAsync+0×9b
0c 00000031`4a42eff0 00007ff9`ee53795d clr!HndScanHandlesForGC+0×137
0d 00000031`4a42f090 00007ff9`ee535769 clr!Ref_TracePinningRoots+0xfd
0e 00000031`4a42f110 00007ff9`ee4a4351 clr!CNameSpace::GcScanHandles+0×4d
0f 00000031`4a42f150 00007ff9`ee55cbe9 clr!SVR::gc_heap::background_mark_phase+0×331
10 00000031`4a42f1e0 00007ff9`ee4a32ed clr!SVR::gc_heap::gc1+0xcd
11 00000031`4a42f240 00007ff9`ee417de6 clr!SVR::gc_heap::bgc_thread_function+0×177
12 00000031`4a42f280 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0×7d
13 00000031`4a42fcc0 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0×22
14 00000031`4a42fcf0 00000000`00000000 ntdll!RtlUserThreadStart+0×34

15  Id: ad8.f9c Suspend: 0 Teb: 00007ff5`ff648000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`f4eddb58 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`f4eddb60 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`f4eddc00 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`f4eddc40 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`f4eddca0 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`f4eddd30 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`f4eddd60 00007ff9`ee780417 clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`f4eddd90 00007ff9`ee4c41e8 clr!SVR::gc_heap::wait_for_bgc_high_memory+0x2b8907
08 00000030`f4edde20 00007ff9`ee355272 clr!SVR::GCHeap::Alloc+0×257
09 00000030`f4edde80 00007ff9`e9f72cfe clr!JIT_New+0×142

0a 00000030`f4ede130 00007ff9`e6e1bf11 System_ServiceModel_ni+0xe72cfe
0b 00000030`f4ede1b0 00007ff9`e6e1be90 System_ServiceModel_Internals_ni+0×4bf11
0c 00000030`f4ede210 00007ff9`ed205156 System_ServiceModel_Internals_ni+0×4be90
0d 00000030`f4ede270 00007ff9`ee35ab53 mscorlib_ni+0×545156
0e 00000030`f4ede2d0 00007ff9`ee35aa3e clr!CallDescrWorkerInternal+0×83
0f 00000030`f4ede310 00007ff9`ee395b80 clr!CallDescrWorkerWithHandler+0×4a
10 00000030`f4ede350 00007ff9`ee9160b8 clr!DispatchCallSimple+0×60
11 00000030`f4ede3e0 00007ff9`ee35c481 clr!BindIoCompletionCallBack_Worker+0xb8
12 00000030`f4ede470 00007ff9`ee35c408 clr!ManagedThreadBase_DispatchInner+0×2d
13 00000030`f4ede4b0 00007ff9`ee35c379 clr!ManagedThreadBase_DispatchMiddle+0×6c
14 00000030`f4ede5b0 00007ff9`ee35c4bb clr!ManagedThreadBase_DispatchOuter+0×75
15 00000030`f4ede640 00007ff9`ee916219 clr!ManagedThreadBase_FullTransitionWithAD+0×2f
16 00000030`f4ede6a0 00007ff9`ee916129 clr!BindIoCompletionCallbackStubEx+0xb9
17 00000030`f4ede720 00007ff9`ee4da72d clr!BindIoCompletionCallbackStub+0×9
18 00000030`f4ede750 00007ff9`ee417de6 clr!ThreadpoolMgr::CompletionPortThreadStart+0×23d
19 00000030`f4ede7f0 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0×7d
1a 00000030`f4edf7b0 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0×22
1b 00000030`f4edf7e0 00000000`00000000 ntdll!RtlUserThreadStart+0×34

16  Id: ad8.d50 Suspend: 0 Teb: 00007ff5`ff64a000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`f4cde038 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`f4cde040 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`f4cde0e0 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`f4cde120 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`f4cde180 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`f4cde210 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`f4cde240 00007ff9`ee780417 clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`f4cde270 00007ff9`ee4c41e8 clr!SVR::gc_heap::wait_for_bgc_high_memory+0x2b8907
08 00000030`f4cde300 00007ff9`ee355272 clr!SVR::GCHeap::Alloc+0×257
09 00000030`f4cde360 00007ff9`e9f72cfe clr!JIT_New+0×142

0a 00000030`f4cde610 00007ff9`e6e1bf11 System_ServiceModel_ni+0xe72cfe
0b 00000030`f4cde690 00007ff9`e6e1be90 System_ServiceModel_Internals_ni+0×4bf11
0c 00000030`f4cde6f0 00007ff9`ed205156 System_ServiceModel_Internals_ni+0×4be90
0d 00000030`f4cde750 00007ff9`ee35ab53 mscorlib_ni+0×545156
0e 00000030`f4cde7b0 00007ff9`ee35aa3e clr!CallDescrWorkerInternal+0×83
0f 00000030`f4cde7f0 00007ff9`ee395b80 clr!CallDescrWorkerWithHandler+0×4a
10 00000030`f4cde830 00007ff9`ee9160b8 clr!DispatchCallSimple+0×60
11 00000030`f4cde8c0 00007ff9`ee35c481 clr!BindIoCompletionCallBack_Worker+0xb8
12 00000030`f4cde950 00007ff9`ee35c408 clr!ManagedThreadBase_DispatchInner+0×2d
13 00000030`f4cde990 00007ff9`ee35c379 clr!ManagedThreadBase_DispatchMiddle+0×6c
14 00000030`f4cdea90 00007ff9`ee35c4bb clr!ManagedThreadBase_DispatchOuter+0×75
15 00000030`f4cdeb20 00007ff9`ee916219 clr!ManagedThreadBase_FullTransitionWithAD+0×2f
16 00000030`f4cdeb80 00007ff9`ee916129 clr!BindIoCompletionCallbackStubEx+0xb9
17 00000030`f4cdec00 00007ff9`ee4da72d clr!BindIoCompletionCallbackStub+0×9
18 00000030`f4cdec30 00007ff9`ee417de6 clr!ThreadpoolMgr::CompletionPortThreadStart+0×23d
19 00000030`f4cdecd0 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0×7d
1a 00000030`f4cdfd10 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0×22
1b 00000030`f4cdfd40 00000000`00000000 ntdll!RtlUserThreadStart+0×34

17  Id: ad8.1584 Suspend: 0 Teb: 00007ff5`ff644000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`f4dde9e8 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`f4dde9f0 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`f4ddea90 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`f4ddead0 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`f4ddeb30 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`f4ddebc0 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`f4ddebf0 00007ff9`ee780417 clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`f4ddec20 00007ff9`ee4c41e8 clr!SVR::gc_heap::wait_for_bgc_high_memory+0x2b8907
08 00000030`f4ddecb0 00007ff9`ee35579d clr!SVR::GCHeap::Alloc+0×257
09 00000030`f4dded10 00007ff9`ee355f32 clr!AllocateArrayEx+0×1a6
0a 00000030`f4ddee40 00007ff9`ed204d4f clr!JIT_NewArr1+0×252

0b 00000030`f4ddf0f0 00007ff9`e6e13574 mscorlib_ni+0×544d4f
0c 00000030`f4ddf150 00007ff9`e6e1bf11 System_ServiceModel_Internals_ni+0×43574
0d 00000030`f4ddf1c0 00007ff9`e6e1be90 System_ServiceModel_Internals_ni+0×4bf11
0e 00000030`f4ddf220 00007ff9`ed205156 System_ServiceModel_Internals_ni+0×4be90
0f 00000030`f4ddf280 00007ff9`ee35ab53 mscorlib_ni+0×545156
10 00000030`f4ddf2e0 00007ff9`ee35aa3e clr!CallDescrWorkerInternal+0×83
11 00000030`f4ddf320 00007ff9`ee395b80 clr!CallDescrWorkerWithHandler+0×4a
12 00000030`f4ddf360 00007ff9`ee9160b8 clr!DispatchCallSimple+0×60
13 00000030`f4ddf3f0 00007ff9`ee35c481 clr!BindIoCompletionCallBack_Worker+0xb8
14 00000030`f4ddf480 00007ff9`ee35c408 clr!ManagedThreadBase_DispatchInner+0×2d
15 00000030`f4ddf4c0 00007ff9`ee35c379 clr!ManagedThreadBase_DispatchMiddle+0×6c
16 00000030`f4ddf5c0 00007ff9`ee35c4bb clr!ManagedThreadBase_DispatchOuter+0×75
17 00000030`f4ddf650 00007ff9`ee916219 clr!ManagedThreadBase_FullTransitionWithAD+0×2f
18 00000030`f4ddf6b0 00007ff9`ee916129 clr!BindIoCompletionCallbackStubEx+0xb9
19 00000030`f4ddf730 00007ff9`ee4da72d clr!BindIoCompletionCallbackStub+0×9
1a 00000030`f4ddf760 00007ff9`ee417de6 clr!ThreadpoolMgr::CompletionPortThreadStart+0×23d
1b 00000030`f4ddf800 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0×7d
1c 00000030`f4ddf840 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0×22
1d 00000030`f4ddf870 00000000`00000000 ntdll!RtlUserThreadStart+0×34

[...]

20  Id: ad8.fcc Suspend: 0 Teb: 00007ff5`ff64c000 Unfrozen
# Child-SP          RetAddr           Call Site
00 00000030`f4fde938 00007ff9`f4121118 ntdll!NtWaitForSingleObject+0xa
01 00000030`f4fde940 00007ff9`ee3594fb KERNELBASE!WaitForSingleObjectEx+0x94
02 00000030`f4fde9e0 00007ff9`ee3594a7 clr!CLREventWaitHelper2+0x38
03 00000030`f4fdea20 00007ff9`ee359430 clr!CLREventWaitHelper+0x1f
04 00000030`f4fdea80 00007ff9`ee533c96 clr!CLREventBase::WaitEx+0x63
05 00000030`f4fdeb10 00007ff9`ee85849a clr!SVR::gc_heap::user_thread_wait+0x58
06 00000030`f4fdeb40 00007ff9`ee780417 clr!SVR::gc_heap::background_gc_wait+0x4a
07 00000030`f4fdeb70 00007ff9`ee4c41e8 clr!SVR::gc_heap::wait_for_bgc_high_memory+0x2b8907
08 00000030`f4fdec00 00007ff9`ee3555f0 clr!SVR::GCHeap::Alloc+0×257
09 00000030`f4fdec60 00007ff9`ee41963a clr!AllocateObject+0×68

0a 00000030`f4fdecf0 00007ff9`ee41983d clr!Thread::GetExposedObject+0×4e
0b 00000030`f4fded90 00007ff9`ee355a3a clr!GetCurrentThreadHelper+0×99
0c 00000030`f4fdeef0 00007ff9`ed162b87 clr!ThreadNative::GetCurrentThread+0×22
0d 00000030`f4fdef20 00007ff9`ed162ab9 mscorlib_ni+0×4a2b87
0e 00000030`f4fdf080 00007ff9`ed1e49c2 mscorlib_ni+0×4a2ab9
0f 00000030`f4fdf0b0 00007ff9`ed1e47ae mscorlib_ni+0×5249c2
10 00000030`f4fdf140 00007ff9`ed18c084 mscorlib_ni+0×5247ae
11 00000030`f4fdf1b0 00007ff9`ee35ab53 mscorlib_ni+0×4cc084
12 00000030`f4fdf250 00007ff9`ee35aa3e clr!CallDescrWorkerInternal+0×83
13 00000030`f4fdf290 00007ff9`ee35b1d2 clr!CallDescrWorkerWithHandler+0×4a
14 00000030`f4fdf2d0 00007ff9`ee40e053 clr!MethodDescCallSite::CallTargetWorker+0×251
15 00000030`f4fdf480 00007ff9`ee35c481 clr!AppDomainTimerCallback_Worker+0×23
16 00000030`f4fdf570 00007ff9`ee35c408 clr!ManagedThreadBase_DispatchInner+0×2d
17 00000030`f4fdf5b0 00007ff9`ee35c379 clr!ManagedThreadBase_DispatchMiddle+0×6c
18 00000030`f4fdf6b0 00007ff9`ee35c4bb clr!ManagedThreadBase_DispatchOuter+0×75
19 00000030`f4fdf740 00007ff9`ee40dfe5 clr!ManagedThreadBase_FullTransitionWithAD+0×2f
1a 00000030`f4fdf7a0 00007ff9`ee40df59 clr!AppDomainTimerCallback+0×66
1b 00000030`f4fdf800 00007ff9`ee40db62 clr!ThreadpoolMgr::AsyncTimerCallbackCompletion+0×36
1c 00000030`f4fdf850 00007ff9`ee540af6 clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0×122
1d 00000030`f4fdf8f0 00007ff9`ee5409ea clr!ThreadpoolMgr::ExecuteWorkRequest+0×46
1e 00000030`f4fdf920 00007ff9`ee417de6 clr!ThreadpoolMgr::WorkerThreadStart+0xf4
1f 00000030`f4fdf9b0 00007ff9`f60413d2 clr!Thread::intermediateThreadProc+0×7d
20 00000030`f4fdfbf0 00007ff9`f6ea54e4 kernel32!BaseThreadInitThunk+0×22
21 00000030`f4fdfc20 00000000`00000000 ntdll!RtlUserThreadStart+0×34

0:000> !runaway
User Mode Time
Thread       Time
8:1960      0 days 1:09:12.218
14:11d4      0 days 0:03:31.937

2:9e8       0 days 0:03:03.250
3:e34       0 days 0:02:41.562
13:f54       0 days 0:02:38.718
4:1338      0 days 0:00:07.984
0:1014      0 days 0:00:00.046
11:1534      0 days 0:00:00.015
7:1798      0 days 0:00:00.015
20:fcc       0 days 0:00:00.000
19:f48       0 days 0:00:00.000
18:1a60      0 days 0:00:00.000
17:1584      0 days 0:00:00.000
16:d50       0 days 0:00:00.000
15:f9c       0 days 0:00:00.000
12:1988      0 days 0:00:00.000
10:14fc      0 days 0:00:00.000
9:1ae0      0 days 0:00:00.000
6:14cc      0 days 0:00:00.000
5:1a50      0 days 0:00:00.000
1:1258      0 days 0:00:00.000

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

Crash Dump Analysis Patterns (Part 25e)

Saturday, May 6th, 2017

Device Stack Trace analysis pattern is about the analysis of a hierarchy of devices based on the current location of IRP Stack Trace:

0: kd> !irp ffffffa80095e6c10
Irp is active with 7 stacks 6 is current (= 0xfffffa80095e6e48)
No Mdl: System buffer=fffffa8007b52380: Thread fffffa8007486060:  Irp stack trace.
cmd  flg cl Device   File     Completion-Context
[N/A(0), N/A(0)]
0  0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0  0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0  0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0  0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0  0 00000000 00000000 00000000-00000000

Args: 00000000 fffffa8008b045f0 00000000 00000000
>[IRP_MJ_DEVICE_CONTROL(e), N/A(0)]
5  0 fffffa80095e6060 fffffa8009883b60 00000000-00000000
\Driver\usbscan
Args: 00000000 00000010 80002010 00000000
[IRP_MJ_DEVICE_CONTROL(e), N/A(0)]
5  0 fffffa8007ee4bd0 fffffa8009883b60 00000000-00000000
\Driver\ksthunk
Args: 00000000 00000010 80002010 00000000

0: kd> !devstack  fffffa80095e6060
!DevObj           !DrvObj            !DevExt           ObjectName
fffffa8007ee4bd0  \Driver\ksthunk    fffffa8007ee4d20  00000098
> fffffa80095e6060  \Driver\usbscan    fffffa80095e61b0  Usbscan0
fffffa80073a3060 \Driver\DriverA    fffffa8007e767e0  00000097
[…]

0: kd> !devobj fffffa8007ee4bd0
Device object (fffffa8007ee4bd0) is for:
00000098 \Driver\ksthunk DriverObject fffffa8006396c60
Current Irp 00000000 RefCount 0 Type 00000019 Flags 00002050
Dacl fffff9a100099e11 DevExt fffffa8007ee4d20 DevObjExt fffffa8007ee4d28
ExtensionFlags (0x00000800)  DOE_DEFAULT_SD_PRESENT
Characteristics (0000000000)
AttachedTo (Lower) fffffa80095e6060 \Driver\usbscan
Device queue is not busy.

0: kd> !devobj fffffa80095e6060
Device object (fffffa80095e6060) is for:
Usbscan0 \Driver\usbscan DriverObject fffffa8007943570
Current Irp 00000000 RefCount 3 Type 00000019 Flags 00002050
Dacl fffff9a100099e11 DevExt fffffa80095e61b0 DevObjExt fffffa80095e6530
ExtensionFlags (0x00000800)  DOE_DEFAULT_SD_PRESENT
Characteristics (0000000000)
AttachedDevice (Upper) fffffa8007ee4bd0 \Driver\ksthunk
AttachedTo (Lower) fffffa80073a3060 \Driver\DriverA

Device queue is not busy.

0: kd> !devobj fffffa80073a3060
Device object (fffffa80073a3060) is for:
00000097 \Driver\DriverA DriverObject fffffa80063bd540
Current Irp 00000000 RefCount 1 Type 00000022 Flags 00003044
Dacl fffff9a100099e11 DevExt fffffa8007e767e0 DevObjExt fffffa80073a31d8 DevNode fffffa80086e1cb0
ExtensionFlags (0x00000800)  DOE_DEFAULT_SD_PRESENT
Characteristics (0x00000080)  FILE_AUTOGENERATED_DEVICE_NAME
AttachedDevice (Upper) fffffa80095e6060 \Driver\usbscan
Device queue is not busy.

The direction of device Stack Trace is from top to bottom, opposite to I/O Request Stack Trace which is from bottom to top.

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

Trace Analysis Patterns (Part 147)

Wednesday, May 3rd, 2017

Often, for Inter-Correlational trace and log analysis, we need to make sure that we have synchronized traces. The one version of Unsynchronized Traces analysis pattern is depicted in the following diagram where one trace ends  (possibly Truncated Trace) before the start of another trace and both were traced within one hour:

If tracing was done in different time zones with different local times specified in logs we can determine whether the traces are synchronized (when time zone information is not available in Basic Facts) by looking at minutes as shown for the third trace in the diagram above. This technique can also be used in trace calibration (see Calibrating Trace).

There is a similar analysis pattern for memory analysis called Unsynchronized Dumps.

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

Crash Dump Analysis Patterns (Part 94b)

Tuesday, May 2nd, 2017

Many OS structures have interesting fields, and it is good to maintain a list of the most useful of them to check in cases of abnormal software behavior. This Value Deviation analysis pattern variant is about structure fields that have values not usually seen in normal cases. For example, we may sometimes encounter Missing Threads in ALPC Wait Chain endpoint process. For example, Main Thread may be missing. The remaining threads may look normal waiting for synchronization objects. However, inspection of _EPROCESS ProcessDelete field shows it is 0y1. This points to the possibility that one of the threads experienced exception, was terminated and triggered process termination which was blocked by the remaining threads. In such a case we may suggest to enable WER to catch such an exception and save a process crash dump (for example, via LocalDumps registry key). Such processes are not easy to catch as Zombies Processes since their number of active threads is non-zero and they still have private memory.

In some cases we may even proactively check structure fields for specific values. For example, we can use one of the techniques to navigate an active process list from Advanced Windows Memory Dump Analysis training and list process image file names together with their ProcessDelete field:

0: kd> dt nt!_EPROCESS ActiveProcessLinks
+0x2f0 ActiveProcessLinks : _LIST_ENTRY

0: kd> !list -t nt!_LIST_ENTRY.Flink -x "? @$extret-2f0; dt nt!_EPROCESS ImageFileName @$extret-2f0; dt nt!_EPROCESS ProcessDelete @$extret-2f0" poi(nt!PsActiveProcessHead)
Evaluate expression: -92874785243072 = ffffab87`e76ac040
+0x450 ImageFileName : [15] "System"
+0x304 ProcessDelete : 0y0

Evaluate expression: -92874719545280 = ffffab87`eb553840
+0x450 ImageFileName : [15] "smss.exe"
+0x304 ProcessDelete : 0y0

Evaluate expression: -92874717837248 = ffffab87`eb6f4840
+0x450 ImageFileName : [15] "csrss.exe"
+0x304 ProcessDelete : 0y0

[...]

Evaluate expression: -92874709187456 = ffffab87`ebf34480
+0x450 ImageFileName : [15] "ServiceA.exe"
+0×304 ProcessDelete : 0y1

[...]

0: kd> !process ffffab87ebf34480 3f
[...]
THREAD ffffab8815527080 [...]
THREAD ffffab87eb41e040 [...]
THREAD ffffab881bf3c800 [...]
[...]

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