Software Diagnostics Library

Critical Stack Trace pattern addresses abnormal behaviour such as page fault processing or any other critical system activity that is waiting too long. Such activity is either finishes quickly or lead to normal bugcheck processing code. For example, this thread is stuck in page fault processing for 32 minutes while loading a resource:

THREAD fffffa80f0603c00  Cid 376.3d6  Teb: 000007fffffd6000 Win32Thread: fffff900c09e0640 WAIT: (Executive) KernelMode Non-Alertable
[...]
Wait Start TickCount      6281298        Ticks: 123391 (0:00:32:04.102)
[…]
Child-SP          RetAddr           Call Site
fffff880`3fc99030 fffff800`01882bd2 nt!KiSwapContext+0×7a
fffff880`3fc99170 fffff800`01893f8f nt!KiCommitThreadWait+0×1d2
fffff880`3fc99200 fffff880`016283ff nt!KeWaitForSingleObject+0×19f
fffff880`3fc992a0 fffff880`01620fc6 Ntfs!NtfsNonCachedIo+0×23f
fffff880`3fc99470 fffff880`01622a68 Ntfs!NtfsCommonRead+0×7a6
fffff880`3fc99610 fffff880`00fb4bcf Ntfs!NtfsFsdRead+0×1b8
fffff880`3fc99820 fffff880`00fb36df fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0×24f
fffff880`3fc998b0 fffff800`018b44f5 fltmgr!FltpDispatch+0xcf
fffff880`3fc999a0 fffff800`018b3fc9 nt!IoPageRead+0×255
fffff880`3fc99a30 fffff800`0189a85a nt!MiIssueHardFault+0×255
fffff880`3fc99ac0 fffff800`0188b2ee nt!MmAccessFault+0×146a
fffff880`3fc99c20 00000000`779da643 nt!KiPageFault+0×16e (TrapFrame @ fffff880`3fd99c20)
00000000`039ff4f0 00000000`779d8b1e ntdll!LdrpGetRcConfig+0xcd
00000000`039ff580 00000000`779da222 ntdll!LdrIsResItemExist+0×1e
00000000`039ff5c0 00000000`779f82c4 ntdll!LdrpSearchResourceSection_U+0xa4
00000000`039ff6e0 000007fe`fe0075c1 ntdll!LdrFindResource_U+0×44
00000000`039ff720 000007fe`fb217777 KERNELBASE!FindResourceExW+0×85
[…]

The Top Blocking Module is NTFS so we might want then to look for other similar stack traces from stack trace collection.

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

Here we publish Active Thread pattern that was previously introduced in Accelerated Mac OS X Core Dump Analysis training. Basically it is a thread that is not waiting or suspended (most threads are). However, from a memory dump it is not possible to find out whether it was spiking at the dump generation time (unless we have a set of memory snapshots and in each one we have the same or similar back trace) and we don’t have any paratext with CPU consumption stats for threads. For example, in one core dump we have these threads:

(gdb) info threads
12 0x98c450ee in __workq_kernreturn ()
11 0x98c4280e in semaphore_wait_trap ()
10 0x98c448e2 in __psynch_cvwait ()
9 0×00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()
8 0×98c428e6 in mach_wait_until ()
7 0×98c448e2 in __psynch_cvwait ()
6 0×98c427d2 in mach_msg_trap ()
5 0×98c427d2 in mach_msg_trap ()
4 0×98c428e6 in mach_wait_until ()
3 0×98c427d2 in mach_msg_trap ()
2 0×98c459ae in kevent ()
*  1 0×014bcee0 in cgGLGetLatestProfile ()

Threads #9 and #1 are not waiting so we inspect their back traces:

(gdb) bt
#0  0x014bcee0 in cgGLGetLatestProfile ()
#1  0x99060dd5 in exit ()
#2  0x001ef859 in os_exit ()
#3  0x001dc873 in luaD_precall ()
#4  0x001e7d9e in luaV_execute ()
#5  0x001dc18b in luaD_rawrunprotected ()
#6  0x001dced4 in lua_resume ()
#7  0x0058a526 in ticLuaManager::executeProgram ()
#8  0x005a09af in ticLuaScript::_execute ()
#9  0x003a6480 in darcScript::execute ()
#10 0x003af4d8 in darcTimeline::execute ()
#11 0x0034a2ba in darcSequenceur::executeAll ()
#12 0x0036904b in darcEventManager::ExecuteEventHandler ()
#13 0x003a37d2 in darcScene::process ()
#14 0x0034a2ba in darcSequenceur::executeAll ()
#15 0x0036904b in darcEventManager::ExecuteEventHandler ()
#16 0x00343ec0 in darcContext::process ()
#17 0x00347339 in darcContext::main ()
#18 0x003cf73d in darcPlayerImpl::renderOneFrame ()
#19 0x003cf078 in darcPlayerImpl::render ()
#20 0x000b1f6f in Run ()
#21 0x000b1fe9 in tiMain ()
#22 0x000c73ee in main ()

(gdb) thread 9
[Switching to thread 9 (core thread 8)]
0x00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()

(gdb) bt
#0  0x00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()
#1  0x0010f936 in ticVideoManager::isPaused ()
#2  0x00201801 in ticMLT_VideoCapture::Execute ()
#3  0x0020aa0b in ticModuleGraph::runOnce ()
#4  0x002632be in TrackingApp::ProcessTracking ()
#5  0x005b2f5d in ticMLTTracking::processInternal ()
#6  0x005b322d in ticMLTTracking::processThread ()
#7  0x005b36f3 in trackingThread ()
#8  0x004eaf1e in ticThread::threadFunc ()
#9  0x99023557 in _pthread_start ()
#10 0x9900dcee in thread_start ()

Windows equivalent would be a process memory dump which doesn’t have any information saved for !runaway WinDbg command.

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

A page to reference all different kinds of optimization patterns is necessary, so I created this post:

• Optimized Code (function parameter reuse)
• OMAP Code Optimization
• Optimized VM Layout
• Inline Function Optimization (unmanaged code)
• Inline Function Optimization (managed code)
• False Function Parameters
• Hidden Parameter

I’ll update it as soon as I add more similar patterns.

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

Not all processes are linked into a list that some commands traverse such as !process 0 0. A processes may unlink itself or be in an initialization stage. However, a process structure is allocated from nonpaged pool and such pool can be searched for ”Proc” pool tag (unless a process changes that in memory). We call such pattern Hidden Process. For example:

0: kd> !poolfind Proc

Searching NonPaged pool (83c3c000 : 8bc00000) for Tag: Proc

*87b15000 size:  298 previous size:    0  (Free)      Pro.
*87b18370 size:  298 previous size:   98  (Allocated) Proc (Protected)
[...]
*8a35e900 size:  298 previous size:   30  (Allocated) Proc (Protected)
*8a484000 size:  298 previous size:    0  (Allocated) Proc (Protected)
*8a4a2d68 size:  298 previous size:   28  (Allocated) Proc (Protected)
[…]

One such structure is missing from active process linked list (note that it has a parent PID):

0: kd> !process 8a484000+20
PROCESS 8a484020  SessionId: 0  Cid: 05a0    Peb: 00000000  ParentCid: 0244
DirBase: bffc2200  ObjectTable: e17e6a78  HandleCount:   0.
Image: AppChild.exe
VadRoot 8a574f80 Vads 4 Clone 0 Private 3. Modified 0. Locked 0.
DeviceMap e1002898
Token                             e1a36030
ElapsedTime                       00:00:00.000
UserTime                          00:00:00.000
KernelTime                        419 Days 13:24:16.625
QuotaPoolUsage[PagedPool]         7580
QuotaPoolUsage[NonPagedPool]      160
Working Set Sizes (now,min,max)  (12, 50, 345) (48KB, 200KB, 1380KB)
PeakWorkingSetSize                12
VirtualSize                       1 Mb
PeakVirtualSize                   1 Mb
PageFaultCount                    5
MemoryPriority                    BACKGROUND
BasePriority                      8
CommitCharge                      156

No active threads

We may think that this process is zombie (note that unlike terminated processes it has a non-zero data such as VAD and object table and zero PEB and elapsed time) but inspection of its parent process thread stacks reveals that it was in the process of creation (note an attached process field):

THREAD 8a35dad8  Cid 0244.0248  Teb: 7ffdd000 Win32Thread: bc3aa688 WAIT: (Unknown) KernelMode Non-Alertable
ba971608  NotificationEvent
Impersonation token:  e2285030 (Level Impersonation)
DeviceMap                 e1a31a58
Owning Process            8a35e920       Image:         AppParent.exe
Attached Process          8a484020       Image:         AppChild.exe
Wait Start TickCount      2099           Ticks: 1 (0:00:00:00.015)
Context Switch Count      279                 LargeStack
UserTime                  00:00:00.046
KernelTime                00:00:00.046
Win32 Start Address AppParent!mainCRTStartup (0×0100d303)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init ba972000 Current ba971364 Base ba972000 Limit ba96e000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
ba97137c 80833f2d nt!KiSwapContext+0×26
ba9713a8 80829c72 nt!KiSwapThread+0×2e5
ba9713f0 bad3c9db nt!KeWaitForSingleObject+0×346
[…]
ba971b94 8094cfc3 nt!MmCreatePeb+0×2cc
ba971ce4 8094d42d nt!PspCreateProcess+0×5a9
ba971d38 8088b4ac nt!NtCreateProcessEx+0×77
ba971d38 7c82845c nt!KiFastCallEntry+0xfc (TrapFrame @ ba971d64)
0006f498 7c826d09 ntdll!KiFastSystemCallRet
0006f49c 77e6cf95 ntdll!ZwCreateProcessEx+0xc
0006fcc0 7d1ec670 kernel32!CreateProcessInternalW+0×15e5
0006fd0c 01008bcf ADVAPI32!CreateProcessAsUserW+0×108
[…]

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

Similar to Network Packet Buildup pattern we also have Disk Packet Buildup. This can be detectable either through SCSI WinDbg extension or using IRP Distribution Anomaly pattern:

0: kd> .load scsikd

0: kd> !scsikd.classext
Storage class devices:

* !classext fffffa80026395b0 [1,2] SAMSUNG HS082HB Paging Disk

Usage: !classext <class device> <level [0-2]>

0: kd> !scsikd.classext fffffa80026395b0
Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

-- dt classpnp!_CLASS_PRIVATE_FDO_DATA fffffa8002648010 --

Classpnp External Information at fffffa8002639700

SAMSUNG HS082HB NL100-01 S140JR0SA00025

Minidriver information at fffffa8002639bc0
Attached device object at fffffa80017ecda0
Physical device object at fffffa80024ab060

Media Geometry:

Bytes in a Sector = 512
Sectors per Track = 63
Tracks / Cylinder = 255
Media Length      = 80026361856 bytes = ~74 GB

-- dt classpnp!_FUNCTIONAL_DEVICE_EXTENSION fffffa8002639700 --

This is a normal case:

0: kd> !scsikd.classext fffffa80026395b0 2
Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

Transfer Packet Engine:

Packet          Status  DL Irp          Opcode  Sector/ListId   UL Irp
--------         ------ --------         ------ --------------- --------
fffffa8002648e80  Free  fffffa800249eac0
fffffa8002644220  Free  fffffa80024aa4f0
fffffa80026898a0  Free  fffffa80019d2b30
fffffa800267ad40  Free  fffffa8001801b90
fffffa800267aa60  Free  fffffa8001835e10
fffffa8002679010  Free  fffffa80019fac40
fffffa8002679770  Free  fffffa8002679500
fffffa80027659a0  Free  fffffa8002764e10
fffffa8002790e80  Free  fffffa800267a6a0
fffffa800278f5e0  Free  fffffa80019d53c0
fffffa8002599410  Free  fffffa8002785600
fffffa80027f7490  Free  fffffa800278ea00
fffffa80027f6e80  Free  fffffa80027f6c80
fffffa80027f69a0  Free  fffffa80027f67a0
fffffa80027f64c0  Free  fffffa80027f62c0
fffffa8002dd4440  Free  fffffa80027fc600
fffffa8002dced30  Free  fffffa8002dceb30
fffffa8002dce850  Free  fffffa8002ddc010
fffffa8002ddc530  Free  fffffa8002ddc330
fffffa8002de2d30  Free  fffffa8002de2b30
fffffa8002de2850  Free  fffffa8002de2650
fffffa8002de2370  Free  fffffa8002de2170
fffffa8002ddbe80  Free  fffffa8002ddbc80
fffffa8002ddb9a0  Free  fffffa8002ddb7a0
fffffa8002dda010  Free  fffffa8002ddae10
[...]

This is not:

0: kd> !scsikd.classext fffffa80026395b0 2

Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

Transfer Packet Engine:

Packet           Status DL Irp           Opcode Sector   UL Irp
--------         ------ --------         ------ -------- --------
fffffa80c71d9560 Queued fffffa80c71d9360   2a   03cbb948 fffffa80c4f269d0 \FileName
fffffa80c77a3360 Queued fffffa80c77a3160   2a   0400f0a8 fffffa80c59c1010 \FileName
fffffa80c6cefe60 Queued fffffa80c6cefc60   2a   0400f128 fffffa80c59c1010 \FileName
fffffa80c6e92260 Queued fffffa80c4f80010   2a   0400f1e8 fffffa80c59c1010 \FileName
fffffa80c79dbca0 Queued fffffa80c79dbaa0   2a   0400c4e8 fffffa80c59c1010 \FileName
fffffa80c83f2d90 Queued fffffa80c3b23bc0   2a   0400f168 fffffa80c59c1010 \FileName
fffffa80c4a94640 Queued fffffa80c4a94440   2a   0400d5e8 fffffa80c59c1010 \FileName
fffffa80c7984010 Queued fffffa80c7984210   2a   0400d328 fffffa80c59c1010 \FileName
fffffa80c6e52be0 Queued fffffa80c6e529e0   2a   0400f1a8 fffffa80c59c1010 \FileName
fffffa80c7afada0 Queued fffffa80c7afaba0   2a   04010268 fffffa80c59c1010 \FileName
fffffa80c7c19d90 Queued fffffa80ca2c5e10   2a   0400c628 fffffa80c59c1010 \FileName
fffffa80c6182d60 Queued fffffa80c6182b60   2a   0400f9a8 fffffa80c59c1010 \FileName
fffffa80c8695ba0 Queued fffffa80c86959a0   2a   0400d128 fffffa80c59c1010 \FileName
fffffa80c6b42b40 Queued fffffa80c6b42940   2a   0400ed28 fffffa80c59c1010 \FileName
fffffa80c5e1ab00 Queued fffffa80c5e1a900   2a   0400eee8 fffffa80c59c1010 \FileName
fffffa80c5d80a30 Queued fffffa80c4841e10   2a   0400fba8 fffffa80c59c1010 \FileName
fffffa80c48255d0 Queued fffffa80c48253d0   2a   040119e8 fffffa80c59c1010 \FileName
fffffa80c718a270 Queued fffffa80c47d0010   2a   0400d1e8 fffffa80c59c1010 \FileName
fffffa80c51a94b0 Queued fffffa80c51a92b0   2a   0400bd28 fffffa80c59c1010 \FileName
fffffa80ca280990 Queued fffffa80c52b2930   2a   0400d268 fffffa80c59c1010 \FileName
fffffa80c586f280 Queued fffffa80c551fe10   2a   0400f068 fffffa80c59c1010 \FileName
fffffa80c8413540 Queued fffffa80c544ae10   2a   04011a68 fffffa80c59c1010 \FileName
fffffa80c544ac60 Queued fffffa80c535ba90   2a   0400e7e8 fffffa80c59c1010 \FileName
fffffa80c4678010 Queued fffffa80c4678230   2a   04011168 fffffa80c59c1010 \FileName
fffffa80c9d94be0 Queued fffffa80c59205e0   2a   0400d4a8 fffffa80c59c1010 \FileName
fffffa80c5920430 Queued fffffa80c59248f0   2a   0400ea68 fffffa80c59c1010 \FileName
fffffa80c737e8f0 Queued fffffa80c737e6f0   2a   0400fee8 fffffa80c59c1010 \FileName
fffffa80c4797c60 Queued fffffa80c5d31800   2a   0400f328 fffffa80c59c1010 \FileName
fffffa80c711d270 Queued fffffa80c76ee390   2a   0400eaa8 fffffa80c59c1010 \FileName
fffffa80c872dba0 Queued fffffa80c872d9a0   2a   0400eb28 fffffa80c59c1010 \FileName
fffffa80c9e67d10 Queued fffffa80c9e67b10   2a   04012168 fffffa80c59c1010 \FileName
fffffa80ca3bb350 Queued fffffa80c66e4370   2a   0400c928 fffffa80c59c1010 \FileName
fffffa80c5894ab0 Queued fffffa80c58948b0   2a   0400c368 fffffa80c59c1010 \FileName
fffffa80c305fe60 Queued fffffa80c305fc60   2a   04013168 fffffa80c59c1010 \FileName
fffffa80c496cce0 Queued fffffa80c496cae0   2a   0400d168 fffffa80c59c1010 \FileName
fffffa80c5e78c60 Queued fffffa80c905c7f0   2a   0400f8a8 fffffa80c59c1010 \FileName
fffffa80c905c640 Queued fffffa80c5c1c410   2a   0400f428 fffffa80c59c1010 \FileName
fffffa80c68ffc40 Queued fffffa80c68ffa40   2a   0400f468 fffffa80c59c1010 \FileName
fffffa80c3aa3e60 Queued fffffa80c3aa3c60   2a   0400c7a8 fffffa80c59c1010 \FileName
fffffa80c5e8dc60 Queued fffffa80c8852cf0   2a   0400f4a8 fffffa80c59c1010 \FileName
fffffa80c90082b0 Queued fffffa80c7907440   2a   04013428 fffffa80c59c1010 \FileName
fffffa80c7907290 Queued fffffa80c67aea80   2a   0400fe68 fffffa80c59c1010 \FileName
fffffa80c67ae8d0 Queued fffffa80c9383cf0   2a   0400f3a8 fffffa80c59c1010 \FileName
fffffa80c8497010 Queued fffffa80c8497270   2a   0400c5e8 fffffa80c59c1010 \FileName
fffffa80c78c7480 Queued fffffa80c78c7280   2a   0400c3e8 fffffa80c59c1010 \FileName
fffffa80c7f37d90 Queued fffffa80c618b480   2a   0400cce8 fffffa80c59c1010 \FileName
fffffa80c618b2d0 Queued fffffa80ca2e9e10   2a   0400ee28 fffffa80c59c1010 \FileName
fffffa80ca2e9c60 Queued fffffa80c5e783f0   2a   0400d8e8 fffffa80c59c1010 \FileName
fffffa80c64e1650 Queued fffffa80c64e1450   2a   0400d0e8 fffffa80c59c1010 \FileName
fffffa80c684dd60 Queued fffffa80c684db60   2a   0400c6a8 fffffa80c59c1010 \FileName
fffffa80c3b2bac0 Queued fffffa80c3b2b8c0   2a   040127a8 fffffa80c59c1010 \FileName
fffffa80c5ff64d0 Queued fffffa80c5ff62d0   2a   0400de68 fffffa80c59c1010 \FileName
fffffa80c99a84b0 Queued fffffa80c99a82b0   2a   0400cfe8 fffffa80c59c1010 \FileName
fffffa80ca300510 Queued fffffa80ca300310   2a   0400c168 fffffa80c59c1010 \FileName
[...]

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

Doing memory dump analysis training for more than 2 years I found that students are divided into 2 types: those who prefer to see source code first and those who want to see a memory dump first. We actually prefer to show a memory dump first and then explore it to find certain patterns of abnormal structure and behavior. Software Diagnostics Services used this approach to design its Accelerated Windows Memory Dump Analysis and Accelerated .NET Memory Dump Analysis courses. Students explore memory dumps and debugger logs to find memory dump analysis patterns which are introduced when necessary. After that they can check source code of modeling applications if they have development experience. Accelerated Windows Software Trace Analysis course uses a different approach. It introduces all software trace analysis patterns at once because they are patterns from software narratology independent from programming languages and software platforms. After that they explore and analyze software traces and logs. We can summarize these 2 approaches on this diagram:

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

Looks like Windows 8 reuses the debugging concept of a frozen thread for the so called a “deeply frozen” process:

0: kd> !sprocess 2
Dumping Session 2
[...]
PROCESS fffffa8002cb2940
SessionId: 2  Cid: 0c80    Peb: 7f6c41dd000  ParentCid: 0288
DeepFreeze
DirBase: 2ef45000  ObjectTable: fffff8a002f215c0  HandleCount: <Data Not Accessible>
Image: iexplore.exe
[…]

0: kd> dt nt!_KPROCESS fffffa8002cb2940
+0x000 Header           : _DISPATCHER_HEADER
+0x018 ProfileListHead  : _LIST_ENTRY [ 0xfffffa80`02cb2958 - 0xfffffa80`02cb2958 ]
+0x028 DirectoryTableBase : 0x2ef45000
+0x030 ThreadListHead   : _LIST_ENTRY [ 0xfffffa80`01e4edf8 - 0xfffffa80`01f5bbf8 ]
+0x040 ProcessLock      : 0
+0x044 Spare0           : 0
+0x048 Affinity         : _KAFFINITY_EX
+0x0f0 ReadyListHead    : _LIST_ENTRY [ 0xfffffa80`02cb2a30 - 0xfffffa80`02cb2a30 ]
+0x100 SwapListEntry    : _SINGLE_LIST_ENTRY
+0x108 ActiveProcessors : _KAFFINITY_EX
+0x1b0 AutoAlignment    : 0y0
+0x1b0 DisableBoost     : 0y0
+0x1b0 DisableQuantum   : 0y0
+0x1b0 AffinitySet      : 0y0
+0×1b0 DeepFreeze       : 0y1
+0×1b0 TimerVirtualization : 0y1
+0×1b0 ActiveGroupsMask : 0y00000000000000000001 (0×1)
+0×1b0 ReservedFlags    : 0y000000 (0)
+0×1b0 ProcessFlags     : 0n112
+0×1b4 BasePriority     : 8 ”
+0×1b5 QuantumReset     : 6 ”
+0×1b6 Visited          : 0 ”
+0×1b7 Flags            : _KEXECUTE_OPTIONS
+0×1b8 ThreadSeed       : [20] 0
+0×208 IdealNode        : [20] 0
+0×230 IdealGlobalNode  : 0
+0×232 Spare1           : 0
+0×234 StackCount       : _KSTACK_COUNT
+0×238 ProcessListEntry : _LIST_ENTRY [ 0xfffffa80`03816b78 - 0xfffffa80`02cc2b78 ]
+0×248 CycleTime        : 0×225078
+0×250 ContextSwitches  : 0×22
+0×258 SchedulingGroup  : (null)
+0×260 FreezeCount      : 0
+0×264 KernelTime       : 0
+0×268 UserTime         : 0
+0×26c LdtFreeSelectorHint : 0
+0×26e LdtTableLength   : 0
+0×270 LdtSystemDescriptor : _KGDTENTRY64
+0×280 LdtBaseAddress   : (null)
+0×288 LdtProcessLock   : _FAST_MUTEX
+0×2c0 InstrumentationCallback : (null)

We also see that all its threads have a freeze count 1:

0: kd> !process fffffa8002cb2940 2
[...]
THREAD fffffa8001e4eb00  Cid 0c80.0514  Teb: 000007f6c41de000 Win32Thread: fffff901000e5b90 WAIT: (Suspended) KernelMode Non-Alertable
FreezeCount 1
fffffa8001e4ede0  NotificationEvent

THREAD fffffa800219c080  Cid 0c80.0d88  Teb: 000007f6c41db000 Win32Thread: fffff90103f206e0 WAIT: (Suspended) KernelMode Non-Alertable
FreezeCount 1
fffffa800219c360  NotificationEvent
[…]

0: kd> dt _KTHREAD fffffa800219c080
nt!_KTHREAD
+0x000 Header           : _DISPATCHER_HEADER
+0x018 SListFaultAddress : (null)
+0x020 QuantumTarget    : 0x18c26200
+0x028 InitialStack     : 0xfffff880`1548ddd0 Void
+0x030 StackLimit       : 0xfffff880`15488000 Void
+0x038 StackBase        : 0xfffff880`1548e000 Void
+0x040 ThreadLock       : 0
+0x048 CycleTime        : 0x15ca97c8
+0x050 CurrentRunTime   : 0
+0x054 ExpectedRunTime  : 0xd77e
+0x058 KernelStack      : 0xfffff880`1548d430 Void
+0x060 StateSaveArea    : 0xfffff880`1548de00 _XSAVE_FORMAT
+0x068 SchedulingGroup  : (null)
+0x070 WaitRegister     : _KWAIT_STATUS_REGISTER
+0x071 Running          : 0 ''
+0x072 Alerted          : [2]  ""
+0x074 KernelStackResident : 0y1
+0x074 ReadyTransition  : 0y0
+0x074 ProcessReadyQueue : 0y0
+0x074 WaitNext         : 0y0
+0x074 SystemAffinityActive : 0y0
+0x074 Alertable        : 0y0
+0x074 CodePatchInProgress : 0y0
+0x074 UserStackWalkActive : 0y0
+0x074 ApcInterruptRequest : 0y0
+0x074 QuantumEndMigrate : 0y0
+0x074 UmsDirectedSwitchEnable : 0y0
+0x074 TimerActive      : 0y0
+0x074 SystemThread     : 0y0
+0x074 ProcessDetachActive : 0y0
+0x074 CalloutActive    : 0y0
+0x074 ScbReadyQueue    : 0y0
+0x074 ApcQueueable     : 0y1
+0x074 ReservedStackInUse : 0y0
+0x074 UmsPerformingSyscall : 0y0
+0x074 Reserved         : 0y0000000000000 (0)
+0x074 MiscFlags        : 0n65537
+0x078 AutoAlignment    : 0y0
+0x078 DisableBoost     : 0y0
+0x078 UserAffinitySet  : 0y0
+0x078 AlertedByThreadId : 0y0
+0x078 QuantumDonation  : 0y0
+0x078 EnableStackSwap  : 0y1
+0x078 GuiThread        : 0y1
+0x078 DisableQuantum   : 0y0
+0x078 ChargeOnlyGroup  : 0y0
+0x078 DeferPreemption  : 0y0
+0x078 QueueDeferPreemption : 0y0
+0x078 ForceDeferSchedule : 0y0
+0x078 ExplicitIdealProcessor : 0y0
+0×078 FreezeCount      : 0y1
+0×078 EtwStackTraceApcInserted : 0y00000000 (0)
+0×078 ReservedFlags    : 0y0000000000 (0)
+0×078 ThreadFlags      : 0n8288
+0×07c Spare0           : 0
+0×080 SystemCallNumber : 0×87
+0×084 Spare1           : 0
+0×088 FirstArgument    : 0×00000000`0000017c Void
+0×090 TrapFrame        : (null)
+0×098 ApcState         : _KAPC_STATE
+0×098 ApcStateFill     : [43]  “???”
+0×0c3 Priority         : 8 ”
+0×0c4 UserIdealProcessor : 1
+0×0c8 WaitStatus       : 0n256
+0×0d0 WaitBlockList    : 0xfffffa80`0219c1c0 _KWAIT_BLOCK
+0×0d8 WaitListEntry    : _LIST_ENTRY [ 0xfffffa80`0418a458 - 0xfffff880`009eb300 ]
+0×0d8 SwapListEntry    : _SINGLE_LIST_ENTRY
+0×0e8 Queue            : 0xfffffa80`03da4bc0 _KQUEUE
+0×0f0 Teb              : 0×000007f6`c41db000 Void
+0×0f8 RelativeTimerBias : 0×00000001`8b165f54
+0×100 Timer            : _KTIMER
+0×140 WaitBlock        : [4] _KWAIT_BLOCK
+0×140 WaitBlockFill4   : [20]  “h???”
+0×154 ContextSwitches  : 0×1817
+0×140 WaitBlockFill5   : [68]  “h???”
+0×184 State            : 0×5 ”
+0×185 NpxState         : 1 ”
+0×186 WaitIrql         : 0 ”
+0×187 WaitMode         : 0 ”
+0×140 WaitBlockFill6   : [116]  “h???”
+0×1b4 WaitTime         : 0xf0172e
+0×140 WaitBlockFill7   : [164]  “h???”
+0×1e4 KernelApcDisable : 0n0
+0×1e6 SpecialApcDisable : 0n0
+0×1e4 CombinedApcDisable : 0
+0×140 WaitBlockFill8   : [40]  “h???”
+0×168 ThreadCounters   : (null)
+0×140 WaitBlockFill9   : [88]  “h???”
+0×198 XStateSave       : (null)
+0×140 WaitBlockFill10  : [136]  “h???”
+0×1c8 Win32Thread      : 0xfffff901`03f206e0 Void
+0×140 WaitBlockFill11  : [176]  “h???”
+0×1f0 Ucb              : (null)
+0×1f8 Uch              : (null)
+0×200 TebMappedLowVa   : (null)
+0×208 QueueListEntry   : _LIST_ENTRY [ 0xfffffa80`02ccf408 - 0xfffffa80`03da4bf0 ]
+0×218 NextProcessor    : 0
+0×21c DeferredProcessor : 1
+0×220 Process          : 0xfffffa80`02cb2940 _KPROCESS
+0×228 UserAffinity     : _GROUP_AFFINITY
+0×228 UserAffinityFill : [10]  “???”
+0×232 PreviousMode     : 1 ”
+0×233 BasePriority     : 8 ”
+0×234 PriorityDecrement : 0 ”
+0×234 ForegroundBoost  : 0y0000
+0×234 UnusualBoost     : 0y0000
+0×235 Preempted        : 0 ”
+0×236 AdjustReason     : 0 ”
+0×237 AdjustIncrement  : 0 ”
+0×238 Affinity         : _GROUP_AFFINITY
+0×238 AffinityFill     : [10]  “???”
+0×242 ApcStateIndex    : 0 ”
+0×243 WaitBlockCount   : 0×1 ”
+0×244 IdealProcessor   : 1
+0×248 ApcStatePointer  : [2] 0xfffffa80`0219c118 _KAPC_STATE
+0×258 SavedApcState    : _KAPC_STATE
+0×258 SavedApcStateFill : [43]  “???”
+0×283 WaitReason       : 0×5 ”
+0×284 SuspendCount     : 0 ”
+0×285 Saturation       : 0 ”
+0×286 SListFaultCount  : 0
+0×288 SchedulerApc     : _KAPC
+0×288 SchedulerApcFill0 : [1]  “??????”
+0×289 ResourceIndex    : 0×1 ”
+0×288 SchedulerApcFill1 : [3]  “???”
+0×28b QuantumReset     : 0×6 ”
+0×288 SchedulerApcFill2 : [4]  “???”
+0×28c KernelTime       : 7
+0×288 SchedulerApcFill3 : [64]  “???”
+0×2c8 WaitPrcb         : (null)
+0×288 SchedulerApcFill4 : [72]  “???”
+0×2d0 LegoData         : (null)
+0×288 SchedulerApcFill5 : [83]  “???”
+0×2db CallbackNestingLevel : 0 ”
+0×2dc UserTime         : 0xa
+0×2e0 SuspendEvent     : _KEVENT
+0×2f8 ThreadListEntry  : _LIST_ENTRY [ 0xfffffa80`01c41378 - 0xfffffa80`01e4edf8 ]
+0×308 MutantListHead   : _LIST_ENTRY [ 0xfffffa80`0219c388 - 0xfffffa80`0219c388 ]
+0×318 ReadOperationCount : 0n392
+0×320 WriteOperationCount : 0n321
+0×328 OtherOperationCount : 0n240
+0×330 ReadTransferCount : 0n1849338
+0×338 WriteTransferCount : 0n1197496
+0×340 OtherTransferCount : 0n4972

This is different when a process is under a debugger and all its threads are frozen except the one that communicates to the debugger like in this case study. In Windows 8 this happens, for example, when we switch to a desktop from IE launched from the start page. Then we would see shortly that iexplore.exe process changes from Running to Suspended in Task Manager Details page. We call this pattern Frozen Process to cover both the new feature and a debugged process case.

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

I was analyzing a raw thread stack when came upon this symbolic address which I thought was coincidental:

363b0030  77777777 advapi32!LsaEnumerateAccountRights+0×56

Forward disasssembly makes sense, isn’t it? And every instruction seems have a purpose

0:000> u 77777777
advapi32!LsaEnumerateAccountRights+0×56:
77777777 a4              movs    byte ptr es:[edi],byte ptr [esi]
77777778 fc              cld
77777779 ffc3            inc     ebx
7777777b 8b65e8          mov     esp,dword ptr [ebp-18h]
7777777e ff75e0          push    dword ptr [ebp-20h]
77777781 ff15e4187377    call    dword ptr [advapi32!_imp__I_RpcMapWin32Status (777318e4)]
77777787 50              push    eax
77777788 e8c6f6fbff      call    advapi32!LsapApiReturnResult (77736e53)

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

We resume our case studies involving multiple patterns. It was reported that a user couldn’t start a session. A complete memory dump was generated and we found 3 sessions there. Looking at the last one we found it incomplete with only 3 processes (a normal running user session after initialization was expected to have more than 3 processes):

0: kd> !session
Sessions on machine: 3
Valid Sessions: 0 1 2

0: kd> !sprocess 2
Dumping Session 2

_MM_SESSION_SPACE fffffa600a3e1000
_MMSESSION        fffffa600a3e1b40
PROCESS fffffa8007f6c040
SessionId: 2  Cid: 242c    Peb: 7fffffd8000  ParentCid: 2374
DirBase: 58350000  ObjectTable: fffff8800f485630  HandleCount: 192.
Image: csrss.exe

PROCESS fffffa8007de8130
SessionId: 2  Cid: 1a48    Peb: 7fffffde000  ParentCid: 2374
DirBase: 15755000  ObjectTable: fffff8800c742010  HandleCount: 240.
Image: winlogon.exe

PROCESS fffffa8004c2e4a0
SessionId: 2  Cid: 17b8    Peb: 7efdf000  ParentCid: 144c
DirBase: a3b80000  ObjectTable: fffff8800bf1d350  HandleCount: 168.
Image: AppA.exe

Looking at AppA process we find its main thread blocked in ALPC request directed to ServiceA process:

0: kd> !process fffffa8004c2e4a0 ff
PROCESS fffffa8004c2e4a0
SessionId: 2  Cid: 17b8    Peb: 7efdf000  ParentCid: 144c
DirBase: a3b80000  ObjectTable: fffff8800bf1d350  HandleCount: 168.
Image: AppA.exe
VadRoot fffffa8006d7f310 Vads 192 Clone 0 Private 572. Modified 2. Locked 0.
DeviceMap fffff88015685f30
Token                             fffff8800a245050
ElapsedTime                       01:58:00.200
UserTime                          00:00:00.000
KernelTime                        00:00:00.015
QuotaPoolUsage[PagedPool]         140256
QuotaPoolUsage[NonPagedPool]      18368
Working Set Sizes (now,min,max)  (2025, 50, 345) (8100KB, 200KB, 1380KB)
PeakWorkingSetSize                2087
VirtualSize                       74 Mb
PeakVirtualSize                   79 Mb
PageFaultCount                    2351
MemoryPriority                    BACKGROUND
BasePriority                      8
CommitCharge                      741
Job                               fffffa80063de710

THREAD fffffa8006db8440  Cid 17b8.20e0  Teb: 000000007efdb000 Win32Thread: fffff900c0b0c4f0 WAIT: (WrLpcReply) UserMode Non-Alertable
fffffa8006db87d0  Semaphore Limit 0x1
Waiting for reply to ALPC Message fffff8800f487cf0 : queued at port fffffa8004b37d90 : owned by process fffffa8004b11c10
Not impersonating
DeviceMap                 fffff88015685f30
Owning Process            fffffa8004c2e4a0       Image:         AppA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      4244174        Ticks: 453096 (0:01:57:59.625)
Context Switch Count      132                 LargeStack
UserTime                  00:00:00.031
KernelTime                00:00:00.109
Win32 Start Address AppA!WinMainCRTStartup (0×00000000658c9866)
Stack Init fffffa6008832db0 Current fffffa6008832670
Base fffffa6008833000 Limit fffffa600882a000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr           Call Site
fffffa60`088326b0 fffff800`01e5ccfa nt!KiSwapContext+0×7f
fffffa60`088327f0 fffff800`01e519bb nt!KiSwapThread+0×13a
fffffa60`08832860 fffff800`01e86b12 nt!KeWaitForSingleObject+0×2cb
fffffa60`088328f0 fffff800`020d40b4 nt!AlpcpSignalAndWait+0×92
fffffa60`08832980 fffff800`020d0b46 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`088329e0 fffff800`020c06ef nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`08832b00 fffff800`01e5a573 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`08832bb0 00000000`77cb76ca nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`08832c20)
00000000`000be3f8 00000000`7578993f ntdll!ZwAlpcSendWaitReceivePort+0xa
00000000`000be400 00000000`7577a996 wow64!whNtAlpcSendWaitReceivePort+0×5f
00000000`000be450 00000000`75813688 wow64!Wow64SystemServiceEx+0xca
00000000`000bed00 00000000`7577ab46 wow64cpu!ServiceNoTurbo+0×28
00000000`000bed90 00000000`7577a14c wow64!RunCpuSimulation+0xa
00000000`000bedc0 00000000`77cabbb3 wow64!Wow64LdrpInitialize+0×4b4
00000000`000bf320 00000000`77cab83c ntdll!LdrpInitializeProcess+0×13eb
00000000`000bf5c0 00000000`77c9660e ntdll! ?? ::FNODOBFM::`string’+0×1fbc9
00000000`000bf670 00000000`00000000 ntdll!LdrInitializeThunk+0xe

0: kd> !alpc /m fffff8800f487cf0

Message @ fffff8800f487cf0
MessageID             : 0x0640 (1600)
CallbackID            : 0x36C184 (3588484)
SequenceNumber        : 0x00000002 (2)
Type                  : LPC_REQUEST
DataLength            : 0x0048 (72)
TotalLength           : 0x0070 (112)
Canceled              : No
Release               : No
ReplyWaitReply        : No
Continuation          : Yes
OwnerPort             : fffffa80061946c0 [ALPC_CLIENT_COMMUNICATION_PORT]
WaitingThread         : fffffa8006db8440
QueueType             : ALPC_MSGQUEUE_PENDING
QueuePort             : fffffa8004b37d90 [ALPC_CONNECTION_PORT]
QueuePortOwnerProcess : fffffa8004b11c10 (ServiceA.exe)
ServerThread          : fffffa80066d44b0
QuotaCharged          : No
CancelQueuePort       : 0000000000000000
CancelSequencePort    : 0000000000000000
CancelSequenceNumber  : 0×00000000 (0)
ClientContext         : 00000000007a5630
ServerContext         : 0000000000000000
PortContext           : 0000000005aa3ef0
CancelPortContext     : 0000000000000000
SecurityData          : 0000000000000000
View                  : 0000000000000000

0: kd> !thread fffffa80066d44b0 ff
THREAD fffffa80066d44b0  Cid 07d0.1bec  Teb: 000007fffffa2000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa800728e420  SynchronizationEvent
Impersonation token:  fffff8800a245050 (Level Impersonation)
DeviceMap                 fffff88015685f30
Owning Process            fffffa8004b11c10       Image:         ServiceA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      4244188        Ticks: 453082 (0:01:57:59.406)
Context Switch Count      43
UserTime                  00:00:00.015
KernelTime                00:00:00.000
Win32 Start Address RPCRT4!ThreadStartRoutine (0×000007feff787780)
Stack Init fffffa6009abbdb0 Current fffffa6009abb940
Base fffffa6009abc000 Limit fffffa6009ab6000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr           Call Site
fffffa60`09abb980 fffff800`01e5ccfa nt!KiSwapContext+0×7f
fffffa60`09abbac0 fffff800`01e519bb nt!KiSwapThread+0×13a
fffffa60`09abbb30 fffff800`020be7c8 nt!KeWaitForSingleObject+0×2cb
fffffa60`09abbbc0 fffff800`01e5a573 nt!NtWaitForSingleObject+0×98
fffffa60`09abbc20 00000000`77cb6eba nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`09abbc20)
00000000`096eedb8 00000000`77c9577a ntdll!ZwWaitForSingleObject+0xa
00000000`096eedc0 00000000`77c95671 ntdll!RtlpWaitOnCriticalSection+0xea
00000000`096eee70 00000000`667dfe24 ntdll!RtlEnterCriticalSection+0xf4
[…]

If we examine ServiceA process we fined a critical section wait chain where a endpoint is blocked in a dialog box:

0: kd> .process /r /p fffffa8004b11c10
Implicit process is now fffffa80`04b11c10
Loading User Symbols

0: kd> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x00000000003a4880
Critical section   = 0x000000006684d4c0
LOCKED
LockCount          = 0×3
WaiterWoken        = No
OwningThread       = 0×00000000000023f0
RecursionCount     = 0×1
LockSemaphore      = 0×608
SpinCount          = 0×0000000000000000
OwningThread       = .thread fffffa8006948650
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
—————————————–
DebugInfo          = 0×00000000003b7140
Critical section   = 0×000000000023f188 (+0×23F188)
LOCKED
LockCount          = 0×2
WaiterWoken        = No
OwningThread       = 0×0000000000000a38
RecursionCount     = 0×1
LockSemaphore      = 0×344
SpinCount          = 0×0000000000000000
OwningThread       = .thread fffffa8005d3ebb0
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.

0: kd> .thread /r /p fffffa8006948650
Implicit thread is now fffffa80`06948650
Implicit process is now fffffa80`04b11c10
Loading User Symbols

0: kd> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP          RetAddr           Call Site
fffffa60`0b5ed980 fffff800`01e5ccfa nt!KiSwapContext+0x7f
fffffa60`0b5edac0 fffff800`01e519bb nt!KiSwapThread+0x13a
fffffa60`0b5edb30 fffff800`020be7c8 nt!KeWaitForSingleObject+0x2cb
fffffa60`0b5edbc0 fffff800`01e5a573 nt!NtWaitForSingleObject+0x98
fffffa60`0b5edc20 00000000`77cb6eba nt!KiSystemServiceCopyEnd+0x13
00000000`089cef08 00000000`77c9577a ntdll!ZwWaitForSingleObject+0xa
00000000`089cef10 00000000`77c95671 ntdll!RtlpWaitOnCriticalSection+0xea
00000000`089cefc0 00000000`667e0ad7 ntdll!RtlEnterCriticalSection+0xf4
[…]

0: kd> .thread /r /p fffffa8005d3ebb0
Implicit thread is now fffffa80`05d3ebb0
Implicit process is now fffffa80`04b11c10
Loading User Symbols

0: kd> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP          RetAddr           Call Site
fffffa60`02ed4c50 fffff800`01e5ccfa nt!KiSwapContext+0x7f
fffffa60`02ed4d90 fffff800`01e625eb nt!KiSwapThread+0x13a
fffffa60`02ed4e00 fffff800`020bfc2e nt!KeWaitForMultipleObjects+0x2eb
fffffa60`02ed4e80 fffff800`020c0273 nt!ObpWaitForMultipleObjects+0x26e
fffffa60`02ed5340 fffff800`01e5a573 nt!NtWaitForMultipleObjects+0xe2
fffffa60`02ed5590 00000000`77cb742a nt!KiSystemServiceCopyEnd+0x13
00000000`034de248 00000000`77a8aff3 ntdll!NtWaitForMultipleObjects+0xa
00000000`034de250 00000000`77bbe2b5 kernel32!WaitForMultipleObjectsEx+0x10b
00000000`034de360 000007fe`fc3d14f2 USER32!RealMsgWaitForMultipleObjectsEx+0x129
00000000`034de400 000007fe`fc3d190f DUser!CoreSC::Wait+0x62
00000000`034de450 000007fe`fc3d188a DUser!CoreSC::WaitMessage+0x6f
00000000`034de490 00000000`77bc538e DUser!MphWaitMessageEx+0x36
00000000`034de4c0 00000000`77cb6db6 USER32!_ClientWaitMessageExMPH+0x1a
00000000`034de510 00000000`77bbd2ba ntdll!KiUserCallbackDispatcherContinue
00000000`034de578 00000000`77bc5118 USER32!NtUserWaitMessage+0xa
00000000`034de580 00000000`77bc5770 USER32!DialogBox2+0×261
00000000`034de600 00000000`77bc57e6 USER32!InternalDialogBox+0×134
00000000`034de660 00000000`77bc5e18 USER32!DialogBoxIndirectParamAorW+0×58
00000000`034de6a0 000007fe`fcf349a6 USER32!DialogBoxIndirectParamW+0×18
[…]

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

The case of an error reporting fault chain led me to First Fault Stack Trace memory dump analysis pattern that corresponds to First Fault software diagnostics pattern proper. Here the term first fault is used for an exception that was either ignored by surrounding code or led to other exceptions or error message boxes with stack traces that masked the first one. Typical examples where it is sometimes possible to get a first exception stack trace include but not limited to:

• Fault in error reporting started as a fault in in some other process
• Hidden exception in user or kernel space
• Double fault
• Nested exception in unmanaged and managed code
• Nested offender

It is also sometimes possible unless a stack region was paged out to get partial stack traces from execution residue when the sequence of return addresses was partially overwritten by subsequently executed code.

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

This is a new pattern that we call Error Reporting Fault. It’s about the faults in error reporting infrastructure. The latter should be guarded against such faults and avoid recursion. Here is a summary example of such a pattern on Windows platforms that involve Windows Error Reporting (WER).

In a complete memory dump we notice thousands of WerFault.exe processes:

0: kd> !process 0 0
[...]
PROCESS fffffa8058010380
SessionId: 2  Cid: 488f0    Peb: 7efdf000  ParentCid: 27cb8
DirBase: 25640c000  ObjectTable: fffff8a06cd2ac50  HandleCount:  54.
Image: WerFault.exe

PROCESS fffffa805bbd5970
SessionId: 2  Cid: 4801c    Peb: 7efdf000  ParentCid: 27cb8
DirBase: 2c3f69000  ObjectTable: fffff8a040563af0  HandleCount:  54.
Image: WerFault.exe

PROCESS fffffa8078aec060
SessionId: 2  Cid: 3feac    Peb: 7efdf000  ParentCid: 488f0
DirBase: abd200000  ObjectTable: fffff8a07851a0a0  HandleCount:  59.
Image: WerFault.exe

PROCESS fffffa805bbe9a10
SessionId: 2  Cid: 3d8b8    Peb: 7efdf000  ParentCid: 4801c
DirBase: 261f91000  ObjectTable: fffff8a02d864d40  HandleCount:  56.
Image: WerFault.exe

PROCESS fffffa805bd29060
SessionId: 2  Cid: 1142c    Peb: 7efdf000  ParentCid: 3feac
DirBase: 429fb3000  ObjectTable: fffff8a0355b42e0  HandleCount:  58.
Image: WerFault.exe

PROCESS fffffa8053d853d0
SessionId: 2  Cid: 1fc4c    Peb: 7efdf000  ParentCid: 3d8b8
DirBase: 714371000  ObjectTable: fffff8a01cb6bba0  HandleCount:  58.
Image: WerFault.exe
[...]

Each process has only one thread running through WOW64 modules so we get its 32-bit stack trace:

0: kd> !process fffffa8075c21b30 ff
[...]
THREAD fffffa807c183b60 Cid 2d3c8.4334c Teb: 000000007efdb000 Win32Thread: fffff900c3f71010 WAIT: (UserRequest) UserMode Non-Alertable
[...]

0: kd> .load wow64exts

0: kd> .process /r /p fffffa8075c21b30
Implicit process is now fffffa80`75c21b30
Loading User Symbols
Loading Wow64 Symbols

0: kd> .thread /w fffffa807c183b60
Implicit thread is now fffffa80`7c183b60
x86 context set

0: kd:x86> k
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP          RetAddr
000bf474 77080bdd ntdll!ZwWaitForMultipleObjects+0x15
000bf510 76bb1a2c KERNELBASE!WaitForMultipleObjectsEx+0x100
000bf558 76bb4208 kernel32!WaitForMultipleObjectsExImplementation+0xe0
000bf574 76bd80a4 kernel32!WaitForMultipleObjects+0x18
000bf5e0 76bd7f63 kernel32!WerpReportFaultInternal+0x186
000bf5f4 76bd7858 kernel32!WerpReportFault+0x70
000bf604 76bd77d7 kernel32!BasepReportFault+0x20
000bf690 776674df kernel32!UnhandledExceptionFilter+0x1af
000bf698 776673bc ntdll!__RtlUserThreadStart+0x62
000bf6ac 77667261 ntdll!_EH4_CallFilterFunc+0x12
000bf6d4 7764b459 ntdll!_except_handler4+0x8e
000bf6f8 7764b42b ntdll!ExecuteHandler2+0x26
000bf71c 7764b3ce ntdll!ExecuteHandler+0x24
000bf7a8 77600133 ntdll!RtlDispatchException+0x127
000bf7b4 000bf7c0 ntdll!KiUserExceptionDispatcher+0xf
WARNING: Frame IP not in any known module. Following frames may be wrong.
000bfb00 77629ef2 0xbf7c0
[…]

We find exception processing and code on stack (return address belongs to stack range). This thread is waiting for another process and it is WerFault.exe too:

0: kd:x86> .effmach AMD64

0: kd> !process fffffa8075c21b30 ff
[...]
THREAD fffffa807c183b60 Cid 2d3c8.4334c Teb: 000000007efdb000 Win32Thread: fffff900c3f71010 WAIT: (UserRequest) UserMode Non-Alertable
fffffa80809c44e0 ProcessObject
[…]

0: kd> !process fffffa80809c44e0
PROCESS fffffa80809c44e0
SessionId: 2  Cid: 33844    Peb: 7efdf000  ParentCid: 2d3c8
DirBase: 9c53f0000  ObjectTable: fffff8a0423d4170  HandleCount: 978.
Image: WerFault.exe
[...]

We go back to our original WerFault process and in its PEB data we find it was called to report a fault from another process with PID 0n189240:

0: kd> !process fffffa8075c21b30 ff
[...]
CommandLine:  'C:\Windows\SysWOW64\WerFault.exe -u -p 189240 -s 3888′
[…]

And it’s WerFault.exe too:

0: kd> !process 0n189240
Searching for Process with Cid == 2e338

PROCESS fffffa8078b659e0
SessionId: 2  Cid: 2e338    Peb: 7efdf000  ParentCid: 47608
DirBase: 201796000  ObjectTable: fffff8a02e664380  HandleCount: 974.
Image: WerFault.exe
[...]

So we see a chain of WerFault.exe processes each processing a fault in the previous one. So there should be a first fault somewhere which we can find in stack trace collection (32-bit stack traces for this example) unless that exception stack trace was paged out due to insufficient memory occupied by WerFault.exe processes.

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

Very useful pattern for the analysis of memory dumps from terminal services environments is Incomplete Session. Normally the session processes include csrss.exe, winlogon.exe, wfshell.exe (in case of Citrix), explorer.exe and a few user defined processes such as winword.exe, for example:

0: kd> !session
Sessions on machine: 6
Valid Sessions: 0 1 3 5 6 8

0: kd> !sprocess 6
Dumping Session 6

_MM_SESSION_SPACE fffffa6009447000
_MMSESSION        fffffa6009447b40
PROCESS fffffa800fcee630
SessionId: 6  Cid: 1974    Peb: 7fffffd5000  ParentCid: 147c
DirBase: 158baf000  ObjectTable: fffff8801ef13b00  HandleCount: 532.
Image: csrss.exe

PROCESS fffffa800fc77040
SessionId: 6  Cid: 1ae4    Peb: 7fffffde000  ParentCid: 147c
DirBase: 15d2b4000  ObjectTable: fffff8802084b570  HandleCount: 238.
Image: winlogon.exe

PROCESS fffffa800fe61040
SessionId: 6  Cid: 1edc    Peb: 7efdf000  ParentCid: 1ec8
DirBase: 14df74000  ObjectTable: fffff88020f486e0  HandleCount: 313.
Image: wfshell.exe

PROCESS fffffa800ff5a660
SessionId: 6  Cid: 2054    Peb: 7fffffdf000  ParentCid: 1dbc
DirBase: 201a81000  ObjectTable: fffff88020dd56e0  HandleCount: 447.
Image: explorer.exe

PROCESS fffffa800fe28040
SessionId: 6  Cid: 1ce4    Peb: 7efdf000  ParentCid: 13a8
DirBase: 11f552000  ObjectTable: fffff8801fe96990  HandleCount: 1842.
Image: WINWORD.EXE

PROCESS fffffa800f119c10
SessionId: 6  Cid: 2074    Peb: 7efdf000  ParentCid: 2054
DirBase: 2d994f000  ObjectTable: fffff8801e76aec0  HandleCount: 673.
Image: iexplore.exe

If we compare with the last session #8 we see that the latter has only 2 processes:

0: kd> !sprocess 8
Dumping Session 8

_MM_SESSION_SPACE fffffa600bafc000
_MMSESSION        fffffa600bafcb40
PROCESS fffffa80103a4480
SessionId: 8  Cid: 2858    Peb: 7fffffdf000  ParentCid: 2660
DirBase: a04bb000  ObjectTable: fffff8801cb926a0  HandleCount: 534.
Image: csrss.exe

PROCESS fffffa801065b770
SessionId: 8  Cid: 2878    Peb: 7fffffdf000  ParentCid: 2660
DirBase: 5da40000  ObjectTable: fffff8801ce5e440  HandleCount: 235.
Image: winlogon.exe

Such anomalies may point to a disconnected session that failed to terminate due to some unresponsive session process or a session that is stuck in session initialization process launch sequence due to threads blocked in wait chains so process threads need to be analyzed.

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

The previous mathematical definition of memory dump is for raw memory dumps. They are not really useful because they require symbol files. Each symbol file entry conceptually is a correspondence between a memory address and a direct sum or product of letters from some alphabet:

00000000`76e82c40: kernel32!WaitForMultipleObjectsExImplementation

So we propose an analytical definition of a memory dump as a direct sum of disjoint memory areas M_t taken during some time interval (t₀, …, t_n) where we replace s_tk having values from Z₂ with S_tq having values from Z_p and cardinality of Z_p depending on a platform (32, 64, etc) plus a symbolic description ∏D_i for each S_tq with cardinality of ”i” set sufficient enough to accommodate the largest symbolic name:

M = ∑M_t where M_t = ∑(S_tq+∏D_i)

or simply

M = ∑∑(S_tq+∏D_i)

This can be visualized as a linear memory space such as a virtual memory space when symbol files are applied to modules one after another. However, all this is not necessary, as a symbol from a virtual address can also be mapped to a physical address if necessary. ∏D_i, in fact, refers to any symbolic description.

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

This is a high contention pattern variant where the contention is around a monitor object. For example, we have a distributed CPU spike for some threads:

0:000> !runaway
 User Mode Time
  Thread       Time
   9:6ff4      0 days 0:07:39.019
  12:6b88      0 days 0:06:19.786
  11:6bf0      0 days 0:06:13.889
  10:6930      0 days 0:06:09.240
  16:3964      0 days 0:05:44.483
  17:6854      0 days 0:05:35.326
  13:668c      0 days 0:05:35.123
  14:5594      0 days 0:05:34.858
  15:7248      0 days 0:05:23.111
   2:c54       0 days 0:00:41.215
   4:1080      0 days 0:00:00.349
   7:10f0      0 days 0:00:00.302
   0:c3c       0 days 0:00:00.271
[...]

If we look at their stack traces we find them all blocked trying to enter a monitor, for example:

0:000> ~*k

[...]

  12  Id: d50.6b88 Suspend: 0 Teb: 000007ff`fffd8000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`1a98e798 000007fe`fd0c1420 ntdll!ZwWaitForMultipleObjects+0xa
00000000`1a98e7a0 00000000`76e82cf3 KERNELBASE!WaitForMultipleObjectsEx+0xe8
00000000`1a98e8a0 000007fe`f82e0669 kernel32!WaitForMultipleObjectsExImplementation+0xb3
00000000`1a98e930 000007fe`f82dbec9 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0xc1
00000000`1a98e9d0 000007fe`f82a0569 mscorwks!Thread::DoAppropriateAptStateWait+0x41
00000000`1a98ea30 000007fe`f82beaec mscorwks!Thread::DoAppropriateWaitWorker+0x191
00000000`1a98eb30 000007fe`f81f1b9a mscorwks!Thread::DoAppropriateWait+0x5c
00000000`1a98eba0 000007fe`f82fd3c9 mscorwks!CLREvent::WaitEx+0xbe
00000000`1a98ec50 000007fe`f81ac6be mscorwks!AwareLock::EnterEpilog+0xc9
00000000`1a98ed20 000007fe`f81c7b2b mscorwks!AwareLock::Enter+0x72
00000000`1a98ed50 000007fe`f87946af mscorwks!AwareLock::Contention+0x1fb
00000000`1a98ee20 000007ff`00161528 mscorwks!JITutil_MonContention+0xdf
00000000`1a98efd0 000007ff`0016140e 0×7ff`00161528
00000000`1a98f040 000007ff`00167271 0×7ff`0016140e
00000000`1a98f0a0 000007fe`f74e2bbb 0×7ff`00167271
00000000`1a98f130 000007fe`f753ed76 mscorlib_ni+0×2f2bbb
00000000`1a98f180 000007fe`f8390282 mscorlib_ni+0×34ed76
00000000`1a98f1d0 000007fe`f8274363 mscorwks!CallDescrWorker+0×82
00000000`1a98f220 000007fe`f8274216 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`1a98f2c0 000007fe`f81c96a7 mscorwks!DispatchCallDebuggerWrapper+0×3e
00000000`1a98f320 000007fe`f830ae42 mscorwks!DispatchCallNoEH+0×5f
00000000`1a98f3a0 000007fe`f81bdc00 mscorwks!AddTimerCallback_Worker+0×92
00000000`1a98f430 000007fe`f82a41a5 mscorwks!ManagedThreadCallState::IsAppDomainEqual+0×4c
00000000`1a98f480 000007fe`f82df199 mscorwks!SVR::gc_heap::make_heap_segment+0×155
00000000`1a98f550 000007fe`f82ececa mscorwks!DoOpenIAssemblyStress::DoOpenIAssemblyStress+0×99
00000000`1a98f590 000007fe`f830c0db mscorwks!AddTimerCallbackEx+0xba
00000000`1a98f650 000007fe`f81ebb37 mscorwks!ThreadpoolMgr::AsyncTimerCallbackCompletion+0×53
00000000`1a98f6b0 000007fe`f81fe92a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0×157
00000000`1a98f750 000007fe`f81bb1fc mscorwks!ThreadpoolMgr::WorkerThreadStart+0×1ba
00000000`1a98f7f0 00000000`76e7652d mscorwks!Thread::intermediateThreadProc+0×78
00000000`1a98fcc0 00000000`76fac521 kernel32!BaseThreadInitThunk+0xd
00000000`1a98fcf0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

[...]

  15  Id: d50.7248 Suspend: 0 Teb: 000007ff`ffee6000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`1c16e6f0 000007fe`f87946af mscorwks!AwareLock::Contention+0×13b
00000000`1c16e7c0 000007ff`0016135e mscorwks!JITutil_MonContention+0xdf
00000000`1c16e970 000007ff`0016726b 0×7ff`0016135e
00000000`1c16e9c0 000007fe`f74e2bbb 0×7ff`0016726b
00000000`1c16ea50 000007fe`f753ed76 mscorlib_ni+0×2f2bbb
00000000`1c16eaa0 000007fe`f8390282 mscorlib_ni+0×34ed76
00000000`1c16eaf0 000007fe`f8274363 mscorwks!CallDescrWorker+0×82
00000000`1c16eb40 000007fe`f8274216 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`1c16ebe0 000007fe`f81c96a7 mscorwks!DispatchCallDebuggerWrapper+0×3e
00000000`1c16ec40 000007fe`f830ae42 mscorwks!DispatchCallNoEH+0×5f
00000000`1c16ecc0 000007fe`f81bdc00 mscorwks!AddTimerCallback_Worker+0×92
00000000`1c16ed50 000007fe`f82a41a5 mscorwks!ManagedThreadCallState::IsAppDomainEqual+0×4c
00000000`1c16eda0 000007fe`f82df199 mscorwks!SVR::gc_heap::make_heap_segment+0×155
00000000`1c16ee70 000007fe`f82ececa mscorwks!DoOpenIAssemblyStress::DoOpenIAssemblyStress+0×99
00000000`1c16eeb0 000007fe`f830c0db mscorwks!AddTimerCallbackEx+0xba
00000000`1c16ef70 000007fe`f81ebb37 mscorwks!ThreadpoolMgr::AsyncTimerCallbackCompletion+0×53
00000000`1c16efd0 000007fe`f81fe92a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0×157
00000000`1c16f070 000007fe`f81bb1fc mscorwks!ThreadpoolMgr::WorkerThreadStart+0×1ba
00000000`1c16f110 00000000`76e7652d mscorwks!Thread::intermediateThreadProc+0×78
00000000`1c16f9e0 00000000`76fac521 kernel32!BaseThreadInitThunk+0xd
00000000`1c16fa10 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

[...]

Thread #15 seems was caught at the time it was trying to enter and not waiting yet. If we check a monitor object the thread #12 tries to enter we see it has an address 01af0be8:

0:000> !u 000007ff`00161528
Normal JIT generated code
[…]
000007ff`00161505 90              nop
000007ff`00161506 48b8f089ae1100000000 mov rax,11AE89F0h
000007ff`00161510 488b00          mov     rax,qword ptr [rax]
000007ff`00161513 48894528        mov     qword ptr [rbp+28h],rax
000007ff`00161517 488b4528        mov     rax,qword ptr [rbp+28h]
000007ff`0016151b 48894518        mov     qword ptr [rbp+18h],rax
000007ff`0016151f 488b4d28        mov     rcx,qword ptr [rbp+28h]
000007ff`00161523 e8b8d422f8      call    mscorwks!JIT_MonEnter (000007fe`f838e9e0)
>>> 000007ff`00161528 90              nop
000007ff`00161529 90              nop
000007ff`0016152a 90              nop
[…]
000007ff`001615d2 4883c430        add     rsp,30h
000007ff`001615d6 5d              pop     rbp
000007ff`001615d7 f3c3            rep ret

0:000> dps 11AE89F0h l1
00000000`11ae89f0  00000000`01af0be8

This object seems to be owned by the thread #17:

0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
 1362 000000001ba7b6c0           15         1 000000001c0173b0  6854  17   0000000001af0be8 System.Object
[…]

This thread seems to be blocked in ALPC:

0:017> k
Child-SP          RetAddr           Call Site
00000000`1d55c9e8 000007fe`fee1a776 ntdll!NtAlpcSendWaitReceivePort+0xa
00000000`1d55c9f0 000007fe`fee14e42 rpcrt4!LRPC_CCALL::SendReceive+0x156
00000000`1d55cab0 000007fe`ff0828c0 rpcrt4!I_RpcSendReceive+0x42
00000000`1d55cae0 000007fe`ff08282f ole32!ThreadSendReceive+0x40
00000000`1d55cb30 000007fe`ff08265b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xa3
00000000`1d55cbd0 000007fe`fef3daaa ole32!CRpcChannelBuffer::SendReceive2+0x11b
00000000`1d55cd90 000007fe`fef3da0c ole32!CAptRpcChnl::SendReceive+0x52
00000000`1d55ce60 000007fe`ff08205d ole32!CCtxComChnl::SendReceive+0x68
00000000`1d55cf10 000007fe`feebfd61 ole32!NdrExtpProxySendReceive+0x45
00000000`1d55cf40 000007fe`ff07f82f rpcrt4!NdrpClientCall2+0x9ea
00000000`1d55d6b0 000007fe`fef3d8a2 ole32!ObjectStublessClient+0x1ad
00000000`1d55da40 000007fe`fa511ba8 ole32!ObjectStubless+0x42
[...] 

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

Learn from this Webinar about phenomenological, hermeneutical and analytical approaches to software diagnostics and its knowledge, foundations, norms, theories, logic, methodology, language, ontology, nature and truth. This seminar is hosted by Software Diagnostics Services.

Title: Introduction to Philosophy of Software Diagnostics
Date: 17th of December, 2012
Time: 19:00 GMT
Duration: 60 minutes

Space is limited.
Reserve your Webinar seat now at:
https://www3.gotomeeting.com/register/872846486

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

We continue with such problem pattern category and discuss Unresponsive Window pattern. The previous one was Error Message Box. We all see hang windows from time to time. This can happen, for example, from a main thread blocked in a wait chain. Some windows become unresponsive only temporary, for example, when a window message loop results in a CPU intensive window procedure code path. When I open large WinDbg logs generated by WinDbg scripts running on a complete memory dump in Notepad it opens up a frozen window for some seconds and sometimes for a minute or two. To get an unresponsive window for a longer time I opened a PDF file with a size of a few MB and I attached WinDbg. I got this stack trace:

0:000> k
Child-SP          RetAddr           Call Site
00000000`001ecce0 000007fe`ff9fdf89 USP10!otlCacheManager::GetNextLookup+0x12a
00000000`001ecd40 000007fe`ff9fa134 USP10!ApplyFeatures+0x489
00000000`001ed000 000007fe`ff9e1600 USP10!SubstituteOtlGlyphs+0x224
00000000`001ed0b0 000007fe`ff9d4b60 USP10!GenericEngineGetGlyphs+0x1000
00000000`001ed450 000007fe`ff9989c5 USP10!ShlShape+0x7a0
00000000`001ed670 000007fe`ff9a7363 USP10!ScriptShape+0x205
00000000`001ed710 000007fe`ff9a8ac9 USP10!RenderItemNoFallback+0x433
00000000`001ed7d0 000007fe`ff9a8d86 USP10!RenderItemWithFallback+0x129
00000000`001ed820 000007fe`ff9aa5f7 USP10!RenderItem+0x36
00000000`001ed870 000007fe`ff99b2c9 USP10!ScriptStringAnalyzeGlyphs+0x277
00000000`001ed910 000007fe`ff30285c USP10!ScriptStringAnalyse+0x399
00000000`001ed990 000007fe`ff3031c1 LPK!EditStringAnalyse+0x1d4
00000000`001eda70 000007fe`fc876c05 LPK!EditCchInWidth+0x4e
00000000`001edad0 000007fe`fc85862e COMCTL32!EditML_BuildchLines+0x221
00000000`001edba0 000007fe`fc878f56 COMCTL32!Edit_ResetTextInfo+0x82
00000000`001edbe0 000007fe`fc85a566 COMCTL32!EditML_WndProc+0x456
00000000`001edcd0 00000000`77a19bd1 COMCTL32!Edit_WndProc+0xe0a
00000000`001edd70 00000000`77a16aa8 USER32!UserCallWinProcCheckWow+0x1ad
00000000`001ede30 00000000`77a16bad USER32!SendMessageWorker+0x682
00000000`001edec0 00000000`ff7f4256 USER32!SendMessageW+0x5c
00000000`001edf10 00000000`ff7f43d6 NOTEPAD!LoadFile+0x7cb
00000000`001ee260 00000000`ff7f1018 NOTEPAD!NPInit+0x802
00000000`001efbb0 00000000`ff7f133c NOTEPAD!WinMain+0xc7
00000000`001efc30 00000000`7764652d NOTEPAD!DisplayNonGenuineDlgWorker+0x2da
00000000`001efcf0 00000000`77b2c521 kernel32!BaseThreadInitThunk+0xd
00000000`001efd20 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

Another notepad.exe instance had this similar stack trace:

0:000> k
Child-SP          RetAddr           Call Site
00000000`0015ca60 000007fe`ff9e2152 USP10!ShapingLibraryInternal::RestoreCharMap+0x12
00000000`0015cab0 000007fe`ff9d80b8 USP10!GenericEngineGetGlyphPositions+0x2a2
00000000`0015ce60 000007fe`ff9d548e USP10!ShapingGetGlyphPositions+0x8c8
00000000`0015d030 000007fe`ff998c72 USP10!ShlPlace+0x2de
00000000`0015d1e0 000007fe`ff9a742d USP10!ScriptPlace+0x1f2
00000000`0015d270 000007fe`ff9a8ac9 USP10!RenderItemNoFallback+0x4fd
00000000`0015d330 000007fe`ff9a8d86 USP10!RenderItemWithFallback+0x129
00000000`0015d380 000007fe`ff9aa5f7 USP10!RenderItem+0x36
00000000`0015d3d0 000007fe`ff99b2c9 USP10!ScriptStringAnalyzeGlyphs+0x277
00000000`0015d470 000007fe`ff30285c USP10!ScriptStringAnalyse+0x399
00000000`0015d4f0 000007fe`ff3031c1 LPK!EditStringAnalyse+0x1d4
00000000`0015d5d0 000007fe`fc876c05 LPK!EditCchInWidth+0x4e
00000000`0015d630 000007fe`fc85862e COMCTL32!EditML_BuildchLines+0x221
00000000`0015d700 000007fe`fc878f56 COMCTL32!Edit_ResetTextInfo+0x82
00000000`0015d740 000007fe`fc85a566 COMCTL32!EditML_WndProc+0x456
00000000`0015d830 00000000`77a19bd1 COMCTL32!Edit_WndProc+0xe0a
00000000`0015d8d0 00000000`77a16aa8 USER32!UserCallWinProcCheckWow+0x1ad
00000000`0015d990 00000000`77a16bad USER32!SendMessageWorker+0x682
00000000`0015da20 00000000`ff7f4256 USER32!SendMessageW+0x5c
00000000`0015da70 00000000`ff7f43d6 NOTEPAD!LoadFile+0×7cb
00000000`0015ddc0 00000000`ff7f1018 NOTEPAD!NPInit+0×802
00000000`0015f710 00000000`ff7f133c NOTEPAD!WinMain+0xc7
00000000`0015f790 00000000`7764652d NOTEPAD!DisplayNonGenuineDlgWorker+0×2da
00000000`0015f850 00000000`77b2c521 kernel32!BaseThreadInitThunk+0xd
00000000`0015f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

This thread is also spiking and all work was done in a Unicode script processor as the PDF file was obviously not an ASCII text file:

0:000> !runaway f
User Mode Time
Thread       Time
0:fa0       0 days 0:00:12.402
Kernel Mode Time
Thread       Time
0:fa0       0 days 0:00:10.826
Elapsed Time
Thread       Time
0:fa0       0 days 0:00:34.654

0:000> lmv m USP10
start             end                 module name
000007fe`ff990000 000007fe`ffa59000   USP10      (pdb symbols)          c:\mss\usp10.pdb\DB4EC1196F91457FBB0A462D9D0AFEC31\usp10.pdb
Loaded symbol image file: C:\Windows\system32\USP10.dll
Image path: C:\Windows\system32\USP10.dll
Image name: USP10.dll
Timestamp:        Sat Nov 20 13:15:33 2010 (4CE7C9F5)
CheckSum:         000C4B61
ImageSize:        000C9000
File version:     1.626.7601.17514
Product version:  1.626.7601.17514
File flags:       0 (Mask 3F)
File OS:          40004 NT Win32
File type:        2.0 Dll
File date:        00000000.00000000
Translations:     0409.04b0
CompanyName:      Microsoft Corporation
ProductName:      Microsoft(R) Uniscribe Unicode script processor
InternalName:     Uniscribe
OriginalFilename: Uniscribe
ProductVersion:   1.0626.7601.17514
FileVersion:      1.0626.7601.17514 (win7sp1_rtm.101119-1850)
FileDescription:  Uniscribe Unicode script processor
LegalCopyright:   © Microsoft Corporation. All rights reserved.

We see LoadFile function and find a file name from execution residue on the raw stack:

0:000> dpu 00000000`0015da70
00000000`0015da70  00000000`00000000
00000000`0015da78  00000000`00000000
00000000`0015da80  00000000`00000000
00000000`0015da88  00000000`00000000
00000000`0015da90  00000000`02b40040 "%PDF-1.4..%µµµµ..1 0 obj..<</Type/Catalog/Pages 2 0 R/L"
00000000`0015da98  00000000`00576a62
00000000`0015daa0  00000000`00000000
00000000`0015daa8  00000000`00000000
00000000`0015dab0  00000000`025c0000
00000000`0015dab8  00000000`00000000
00000000`0015dac0  00000000`00000000
00000000`0015dac8  00000000`00000100
00000000`0015dad0  00000000`00000000
00000000`0015dad8  00000000`025c0000
00000000`0015dae0  00000000`00000265
00000000`0015dae8  00000000`ff800b40 "C:\DL\History-Russian-Literature-VIII-Volume2.pdf"
[...]

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

This is a variant of Handled Exception pattern in kernel space (similar to user and managed spaces). The crash dump was the same as in Hidden Exception in kernel space pattern:

fffff880`0a83d910  00000000`00000000
fffff880`0a83d918  fffff6fc`40054fd8
fffff880`0a83d920  fffff880`0a83dca0
fffff880`0a83d928  fffff800`016bcc1c nt!_C_specific_handler+0xcc
fffff880`0a83d930  00000000`00000000
fffff880`0a83d938  00000000`00000000
fffff880`0a83d940  00000000`00000000
fffff880`0a83d948  00000000`00000000
fffff880`0a83d950  fffff800`0189ee38 nt!BBTBuffer <PERF> (nt+0x280e38)
fffff880`0a83d958  fffff880`0a83e940
fffff880`0a83d960  fffff800`016ad767 nt!IopCompleteRequest+0x147
fffff880`0a83d968  fffff880`0a83de40
fffff880`0a83d970  fffff800`01665e40 nt!_GSHandlerCheck_SEH
fffff880`0a83d978  fffff800`017e5338 nt!_imp_NtOpenSymbolicLinkObject+0xfe30
fffff880`0a83d980  fffff880`0a83e310
fffff880`0a83d988  00000000`00000000
fffff880`0a83d990  00000000`00000000
fffff880`0a83d998  fffff800`016b42dd nt!RtlpExecuteHandlerForException+0xd
fffff880`0a83d9a0  fffff800`017d7d0c nt!_imp_NtOpenSymbolicLinkObject+0×2804
fffff880`0a83d9a8  fffff880`0a83eab0
fffff880`0a83d9b0  00000000`00000000

0: kd> ub fffff800`016b42dd
nt!RtlpExceptionHandler+0x24:
fffff800`016b42c4 cc              int     3
fffff800`016b42c5 cc              int     3
fffff800`016b42c6 cc              int     3
fffff800`016b42c7 cc              int     3
fffff800`016b42c8 0f1f840000000000 nop     dword ptr [rax+rax]
nt!RtlpExecuteHandlerForException:
fffff800`016b42d0 4883ec28        sub     rsp,28h
fffff800`016b42d4 4c894c2420      mov     qword ptr [rsp+20h],r9
fffff800`016b42d9 41ff5130        call    qword ptr [r9+30h]

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

This is an example of Hidden Exception pattern in kernel space:

0: kd> !thread
THREAD fffffa800d4bf9c0  Cid 0e88.56e0  Teb: 000007fffffd8000 Win32Thread: 0000000000000000 RUNNING on processor 0
Not impersonating
DeviceMap                 fffff8a001e91950
Owning Process            fffffa800b33cb30       Image:         svchost.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      13154529       Ticks: 0
Context Switch Count      1426
UserTime                  00:00:00.015
KernelTime                00:00:00.124
Win32 Start Address 0x0000000077728d20
Stack Init fffff8800a83fdb0 Current fffff8800a83eb90
Base fffff8800a840000 Limit fffff8800a83a000 Call 0
Priority 10 BasePriority 10 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
[…]

0: kd> dps fffff8800a83a000 fffff8800a840000
[...]
fffff880`0a83e180  fffff880`0a83ea10
fffff880`0a83e188  fffff880`0a83e6d0
fffff880`0a83e190  fffff880`0a83e968
fffff880`0a83e198  fffff800`016c88cf nt!KiDispatchException+0×16f
fffff880`0a83e1a0  fffff880`0a83e968
fffff880`0a83e1a8  fffff880`0a83e1d0
fffff880`0a83e1b0  fffff880`00000000
fffff880`0a83e1b8  00000000`00000000
fffff880`0a83e1c0  00000000`00000000
fffff880`0a83e1c8  00000000`00000000
[…]

0: kd> .cxr fffff880`0a83e1d0
rax=0000000000000009 rbx=fffffa800d4c1de0 rcx=0000000000000000
rdx=fffff8800a83ece0 rsi=0000000000000000 rdi=0000000000000000
rip=fffff800016ad74f rsp=fffff8800a83eba0 rbp=00000000a000000c
r8=fffff8800a83ecd8  r9=fffff8800a83ecc0 r10=0000000000000000
r11=fffff8800a83ed58 r12=0000000000000000 r13=0000000000000000
r14=fffffa800d4bf9c0 r15=fffffa800d4c1ea0
iopl=0  nv up ei pl zr na po nc
cs=0010  ss=0018  ds=002b  es=002b  fs=0053  gs=002b  efl=00010246
nt!IopCompleteRequest+0x12f:
fffff800`016ad74f 48894108 mov qword ptr [rcx+8],rax ds:002b:00000000`00000008=????????????????

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

This is the first pattern that emerged after applying the same pattern-driven software diagnostics methodology to Mac OS X. I had problems using GDB which is so portable that hardly has operating system support like WinDbg has. Fortunately, I found a workaround by complementing core dumps with logs and reports from OS such as crash reports and vmmap data. I call this pattern Paratext which I borrowed from the concept of an extended software trace and software narratology where it borrowed the same concept from literary interpretation (paratext). Typical examples of such pattern usage can be the list of modules with version and path info, application crash specific information, memory region names with attribution and boundaries:

// from .crash reports

0x108f99000 - 0x109044ff7 com.apple.FontBook (198.4 - 198) <7244D36E-4563-3E42-BA46-1F279D30A6CE> /Applications/Font Book.app/Contents/MacOS/Font Book

Exception Type: EXC_BAD_INSTRUCTION (SIGILL)
Exception Codes: 0x0000000000000001, 0x0000000000000000

Application Specific Information:
objc[195]: garbage collection is OFF
*** error for object 0x7fd7fb818e08: incorrect checksum for freed object - object was probably modified after being freed.

// from vmmap logs

[...]
==== Writable regions for process 966
[...]
Stack 0000000101f71000-0000000101ff3000 [ 520K] rw-/rwx SM=PRV thread 1
MALLOC_LARGE 0000000103998000-00000001039b8000 [ 128K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
MALLOC_SMALL (freed) 00000001039b9000-00000001039bb000 [ 8K] rw-/rwx SM=PRV
mapped file 0000000103a05000-0000000103f32000 [ 5300K] rw-/rwx SM=COW ...box.framework/Versions/A/Resources/Extras2.rsrc
mapped file 0000000104409000-00000001046d2000 [ 2852K] rw-/rwx SM=COW /System/Library/Fonts/Helvetica.dfont
MALLOC_LARGE 0000000104f6e000-0000000104f8e000 [ 128K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
MALLOC_LARGE (freed) 0000000108413000-0000000108540000 [ 1204K] rw-/rwx SM=COW
MALLOC_LARGE (freed) 0000000108540000-0000000108541000 [ 4K] rw-/rwx SM=PRV
MALLOC_TINY 00007fefe0c00000-00007fefe0d00000 [ 1024K] rw-/rwx SM=COW DefaultMallocZone_0x101e6e000
MALLOC_TINY 00007fefe0d00000-00007fefe0e00000 [ 1024K] rw-/rwx SM=PRV DispatchContinuations_0x101f38000
MALLOC_TINY 00007fefe0e00000-00007fefe0f00000 [ 1024K] rw-/rwx SM=COW DefaultMallocZone_0x101e6e000
MALLOC_SMALL 00007fefe1000000-00007fefe107b000 [ 492K] rw-/rwx SM=ZER DefaultMallocZone_0x101e6e000
MALLOC_SMALL 00007fefe107b000-00007fefe1083000 [ 32K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
MALLOC_SMALL 00007fefe1083000-00007fefe1149000 [ 792K] rw-/rwx SM=ZER DefaultMallocZone_0x101e6e000
MALLOC_SMALL (freed) 00007fefe1149000-00007fefe1166000 [ 116K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
MALLOC_SMALL (freed) 00007fefe1166000-00007fefe1800000 [ 6760K] rw-/rwx SM=ZER DefaultMallocZone_0x101e6e000
MALLOC_SMALL 00007fefe1800000-00007fefe18ff000 [ 1020K] rw-/rwx SM=ZER DefaultMallocZone_0x101e6e000
MALLOC_SMALL (freed) 00007fefe18ff000-00007fefe1901000 [ 8K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
MALLOC_SMALL 00007fefe1901000-00007fefe2000000 [ 7164K] rw-/rwx SM=ZER DefaultMallocZone_0x101e6e000
MALLOC_TINY (freed) 00007fefe2000000-00007fefe2100000 [ 1024K] rw-/rwx SM=PRV DispatchContinuations_0x101f38000
MALLOC_TINY 00007fefe2100000-00007fefe2200000 [ 1024K] rw-/rwx SM=PRV DefaultMallocZone_0x101e6e000
Stack 00007fff61186000-00007fff61985000 [ 8188K] rw-/rwx SM=ZER thread 0
Stack 00007fff61985000-00007fff61986000 [ 4K] rw-/rwx SM=COW
[...]

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

Forthcoming Training: Accelerated Mac OS X Core Dump Analysis

This is a Mac OS X / GDB counterpart to Truncated Dump pattern previously described for Windows platforms:

(gdb) info threads
Cannot access memory at address 0x7fff885e9e42
4 0x00007fff885e9e42 in ?? ()
3 0x00007fff885e9e42 in ?? ()
2 0x00007fff885e9e42 in ?? ()
* 1 0x00007fff885e9e42 in ?? ()
warning: Couldn't restore frame in current thread, at frame 0
0x00007fff885e9e42 in ?? ()

(gdb) disass 0x00007fff885e9e42
No function contains specified address.

(gdb) info r rsp
rsp 0x7fff67fe8a18 0x7fff67fe8a18

(gdb) x/100a 0x7fff67fe8a18
0x7fff67fe8a18: Cannot access memory at address 0x7fff67fe8a18

This often happens if there is no space to save a full core dump.

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

Forthcoming Training: Accelerated Mac OS X Core Dump Analysis