Crash Dump Analysis Patterns (Part 33)
Monday, November 5th, 2007If there are no CPU-bound threads on a system then most of the time processors are looping in the so called idle thread where they are halted waiting for an interrupt to occur (HLT instruction). When an interrupt occurs they process a DPC list and then do thread scheduling if necessary as evident from stack trace and its functions disassembly below. If we have a memory dump one of running threads would be the one that called KeBugCheck(Ex) function. In examples below crash dumps were generated by SystemDump application:
3: kd> !running
System Processors f (affinity mask)
Idle Processors d
Prcb Current Next
1 f7737120 8a3da020 ................
3: kd> !thread 8a3da020 1f
THREAD 8a3da020 Cid 0ebc.0dec Teb: 7ffdf000 Win32Thread: bc002328 RUNNING on processor 1
Not impersonating
DeviceMap e3e3e080
Owning Process 8a0aea88 Image: SystemDump.exe
Wait Start TickCount 17154 Ticks: 0
Context Switch Count 568 LargeStack
UserTime 00:00:00.046
KernelTime 00:00:00.375
Win32 Start Address 0x0040fe92
Start Address 0x77e6b5c7
Stack Init f4266000 Current f4265c08 Base f4266000 Limit f4261000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
f4265bec f79c9743 nt!KeBugCheckEx+0x1b
WARNING: Stack unwind information not available. Following frames may be wrong.
f4265c38 8081dce5 SystemDump+0x743
f4265c4c 808f4797 nt!IofCallDriver+0x45
f4265c60 808f5515 nt!IopSynchronousServiceTail+0x10b
f4265d00 808ee0e4 nt!IopXxxControlFile+0x5db
f4265d34 80888c6c nt!NtDeviceIoControlFile+0x2a
f4265d34 7c82ed54 nt!KiFastCallEntry+0xfc
3: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state
3: kd> ~2s
2: kd> !thread -1 1f
THREAD f7742090 Cid 0000.0000 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 2
Not impersonating
Owning Process 8089db40 Image: Idle
Wait Start TickCount 0 Ticks: 17154 (0:00:04:28.031)
Context Switch Count 193155
UserTime 00:00:00.000
KernelTime 00:03:23.328
Stack Init f78b7000 Current f78b6d4c Base f78b7000 Limit f78b4000 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr
f78b6d50 8088d262 intelppm!AcpiC1Idle+0x12
f78b6d54 00000000 nt!KiIdleLoop+0xa
2: kd> .asm no_code_bytes
Assembly options: no_code_bytes
2: kd> uf intelppm!AcpiC1Idle
intelppm!AcpiC1Idle:
f6e73c90 push ecx
f6e73c91 push 0
f6e73c93 call intelppm!KeQueryPerformanceCounter (f6e740c6)
f6e73c98 mov ecx,dword ptr [esp]
f6e73c9b mov dword ptr [ecx],eax
f6e73c9d mov dword ptr [ecx+4],edx
f6e73ca0 sti
f6e73ca1 hlt
f6e73ca2 push 0
f6e73ca4 call intelppm!KeQueryPerformanceCounter (f6e740c6)
f6e73ca9 pop ecx
f6e73caa mov dword ptr [ecx+8],eax
f6e73cad mov dword ptr [ecx+0Ch],edx
f6e73cb0 xor eax,eax
f6e73cb2 ret
2: kd> uf nt!KiIdleLoop
nt!KiIdleLoop:
8088d258 jmp nt!KiIdleLoop+0xa (8088d262)
nt!KiIdleLoop+0x2:
8088d25a lea ecx,[ebx+0EC0h]
8088d260 call dword ptr [ecx]
nt!KiIdleLoop+0xa:
8088d262 pause
8088d264 sti
8088d265 nop
8088d266 nop
8088d267 cli
8088d268 mov eax,dword ptr [ebx+0A4Ch]
8088d26e or eax,dword ptr [ebx+0A88h]
8088d274 or eax,dword ptr [ebx+0C10h]
8088d27a je nt!KiIdleLoop+0×37 (8088d28f)
nt!KiIdleLoop+0x24:
8088d27c mov cl,2
8088d27e call dword ptr [nt!_imp_HalClearSoftwareInterrupt (808010a8)]
8088d284 lea ecx,[ebx+120h]
8088d28a call nt!KiRetireDpcList (80831be8)
nt!KiIdleLoop+0x37:
8088d28f cmp dword ptr [ebx+128h],0
8088d296 je nt!KiIdleLoop+0xca (8088d322)
nt!KiIdleLoop+0x44:
8088d29c mov ecx,1Bh
8088d2a1 call dword ptr [nt!_imp_KfRaiseIrql (80801100)]
8088d2a7 sti
8088d2a8 mov edi,dword ptr [ebx+124h]
8088d2ae mov byte ptr [edi+5Dh],1
8088d2b2 lock bts dword ptr [ebx+0A7Ch],0
8088d2bb jae nt!KiIdleLoop+0x70 (8088d2c8)
nt!KiIdleLoop+0x65:
8088d2bd lea ecx,[ebx+0A7Ch]
8088d2c3 call nt!KefAcquireSpinLockAtDpcLevel (80887fd0)
nt!KiIdleLoop+0x70:
8088d2c8 mov esi,dword ptr [ebx+128h]
8088d2ce cmp esi,edi
8088d2d0 je nt!KiIdleLoop+0xb3 (8088d30b)
nt!KiIdleLoop+0x7a:
8088d2d2 and dword ptr [ebx+128h],0
8088d2d9 mov dword ptr [ebx+124h],esi
8088d2df mov byte ptr [esi+4Ch],2
8088d2e3 and byte ptr [ebx+0AA3h],0
8088d2ea and dword ptr [ebx+0A7Ch],0
nt!KiIdleLoop+0x99:
8088d2f1 mov ecx,1
8088d2f6 call nt!SwapContext (8088d040)
8088d2fb mov ecx,2
8088d300 call dword ptr [nt!_imp_KfLowerIrql (80801104)]
8088d306 jmp nt!KiIdleLoop+0xa (8088d262)
nt!KiIdleLoop+0xb3:
8088d30b and dword ptr [ebx+128h],0
8088d312 and dword ptr [ebx+0A7Ch],0
8088d319 and byte ptr [edi+5Dh],0
8088d31d jmp nt!KiIdleLoop+0xa (8088d262)
nt!KiIdleLoop+0xca:
8088d322 cmp byte ptr [ebx+0AA3h],0
8088d329 je nt!KiIdleLoop+0x2 (8088d25a)
nt!KiIdleLoop+0xd7:
8088d32f sti
8088d330 lea ecx,[ebx+120h]
8088d336 call nt!KiIdleSchedule (808343e6)
8088d33b test eax,eax
8088d33d mov esi,eax
8088d33f mov edi,dword ptr [ebx+12Ch]
8088d345 jne nt!KiIdleLoop+0x99 (8088d2f1)
nt!KiIdleLoop+0xef:
8088d347 jmp nt!KiIdleLoop+0xa (8088d262)
In some memory dumps taken when systems or sessions were hanging or very slow for some time we might see Busy System pattern where all processors execute non-idle threads and there are threads in ready queues waiting to be scheduled:
3: kd> !running
System Processors f (affinity mask)
Idle Processors 0
Prcb Current Next
0 ffdff120 88cef850 ................
1 f7727120 8940b7a0 ................
2 f772f120 8776f020 ................
3 f7737120 87b25360 ................
3: kd> !ready
Processor 0: Ready Threads at priority 8
THREAD 88161668 Cid 3d58.43a0 Teb: 7ffdf000 Win32Thread: bc1eba48 READY
THREAD 882d0020 Cid 1004.0520 Teb: 7ffdf000 Win32Thread: bc230838 READY
THREAD 88716b40 Cid 2034.241c Teb: 7ffdd000 Win32Thread: bc11b388 READY
THREAD 88bf7978 Cid 2444.2564 Teb: 7ffde000 Win32Thread: bc1ccc18 READY
THREAD 876f7a28 Cid 2308.4bfc Teb: 7ffdd000 Win32Thread: bc1f7b98 READY
Processor 0: Ready Threads at priority 0
THREAD 8a3925a8 Cid 0004.0008 Teb: 00000000 Win32Thread: 00000000 READY
Processor 1: Ready Threads at priority 9
THREAD 87e69db0 Cid 067c.3930 Teb: 7ffdb000 Win32Thread: bc180990 READY
Processor 1: Ready Threads at priority 8
THREAD 88398c70 Cid 27cc.15b4 Teb: 7ffde000 Win32Thread: bc159ea8 READY
Processor 2: Ready Threads at priority 8
THREAD 8873cdb0 Cid 4c24.4384 Teb: 7ffdd000 Win32Thread: bc1c9838 READY
THREAD 89f331e0 Cid 453c.4c68 Teb: 7ffdf000 Win32Thread: bc21dbd0 READY
THREAD 889a03f0 Cid 339c.2fcc Teb: 7ffdf000 Win32Thread: bc1cdbe8 READY
THREAD 87aacdb0 Cid 3b80.4ed0 Teb: 7ffde000 Win32Thread: bc1c5d10 READY
Processor 3: No threads in READY state
Here is another example from busy 8-processor system where only one processor was idle at the time of the bugcheck:
5: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state
Processor 4: No threads in READY state
Processor 5: No threads in READY state
Processor 6: No threads in READY state
Processor 7: No threads in READY state
5: kd> !running
System Processors ff (affinity mask)
Idle Processors 1
Prcb Current Next
1 f7727120 8713a5a0 ................
2 f772f120 86214750 ................
3 f7737120 86f87020 ................
4 f773f120 86ffe700 ................
5 f7747120 86803a90 ................
6 f774f120 86043db0 ................
7 f7757120 86bcbdb0 ................
5: kd> !thread 8713a5a0 1f
THREAD 8713a5a0 Cid 4ef4.4f04 Teb: 7ffdd000 Win32Thread: bc423920 RUNNING on processor 1
Not impersonating
DeviceMap e44e9a40
Owning Process 864d1d88 Image: SomeExe.exe
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 7621092 LargeStack
UserTime 00:06:59.218
KernelTime 00:19:26.359
Win32 Start Address BROWSEUI!BrowserProtectedThreadProc (0x75ec1c3f)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b68b8a70 Current b68b8c28 Base b68b9000 Limit b68b1000 Call b68b8a7c
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
00c1f4fc 773dc4e4 USER32!DispatchHookA+0x35
00c1f528 7739c9c6 USER32!fnHkINLPCWPRETSTRUCTA+0x60
00c1f550 7c828536 USER32!__fnDWORD+0x24
00c1f550 808308f4 ntdll!KiUserCallbackDispatcher+0x2e
b68b8a94 8091d6d1 nt!KiCallUserMode+0x4
b68b8aec bf8a26d3 nt!KeUserModeCallback+0x8f
b68b8b70 bf89dd4d win32k!SfnDWORD+0xb4
b68b8be8 bf89d79d win32k!xxxHkCallHook+0x22c
b68b8c90 bf89da19 win32k!xxxCallHook2+0x245
b68b8cac bf8a137a win32k!xxxCallHook+0x26
b68b8cec bf85af67 win32k!xxxSendMessageTimeout+0x1e3
b68b8d10 bf8c182c win32k!xxxWrapSendMessage+0x1b
b68b8d40 8088978c win32k!NtUserMessageCall+0x9d
b68b8d40 7c8285ec nt!KiFastCallEntry+0xfc
00c1f550 7c828536 ntdll!KiFastSystemCallRet
00c1f57c 7739d1ec ntdll!KiUserCallbackDispatcher+0x2e
00c1f5b8 7738cee9 USER32!NtUserMessageCall+0xc
00c1f5d8 01438f73 USER32!SendMessageA+0x7f
5: kd> !thread 86214750
THREAD 86214750 Cid 0b94.1238 Teb: 7ffdb000 Win32Thread: bc2f5ea8 RUNNING on processor 2
Not impersonating
DeviceMap e3482310
Owning Process 85790020 Image: SomeExe.exe
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 1745682 LargeStack
UserTime 00:01:20.031
KernelTime 00:04:03.484
Win32 Start Address 0x75ec1c3f
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b4861000 Current b4860558 Base b4861000 Limit b4856000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr Args to Child
b4860bd8 bf8da699 8623ebc8 bc2f5ea8 00000000 nt!PsGetThreadProcess
b4860bf4 bf89d6e6 8623ebc8 0010a198 be654f38 win32k!IsRestricted+0x2f
b4860c90 bf89da19 be631660 00000000 00000000 win32k!xxxCallHook2+0x12d
b4860cac bf8a137a 00000000 00000000 00000002 win32k!xxxCallHook+0x26
b4860cec bf85af67 be654f38 0000110a 00000001 win32k!xxxSendMessageTimeout+0x1e3
b4860d10 bf8c182c be654f38 0000110a 00000001 win32k!xxxWrapSendMessage+0x1b
b4860d40 8088978c 00250238 0000110a 00000001 win32k!NtUserMessageCall+0x9d
b4860d40 7c8285ec 00250238 0000110a 00000001 nt!KiFastCallEntry+0xfc
00c1f5fc 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet
5: kd> !thread 86f87020 1f
THREAD 86f87020 Cid 0238.0ae8 Teb: 7ffa5000 Win32Thread: 00000000 RUNNING on processor 3
IRP List:
86869200: (0006,0094) Flags: 00000900 Mdl: 00000000
85b2a7f0: (0006,0094) Flags: 00000900 Mdl: 00000000
86f80a20: (0006,0094) Flags: 00000800 Mdl: 00000000
85e6af68: (0006,0094) Flags: 00000900 Mdl: 00000000
892a6c78: (0006,0094) Flags: 00000900 Mdl: 00000000
85d06070: (0006,0094) Flags: 00000900 Mdl: 00000000
85da35e0: (0006,0094) Flags: 00000900 Mdl: 00000000
87216340: (0006,0094) Flags: 00000900 Mdl: 00000000
Not impersonating
DeviceMap e1003940
Owning Process 8850e020 Image: lsass.exe
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 39608
UserTime 00:00:01.625
KernelTime 00:00:05.437
Win32 Start Address RPCRT4!ThreadStartRoutine (0x77c7b0f5)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init f4925000 Current f4924c38 Base f4925000 Limit f4922000 Call 0
Priority 10 BasePriority 9 PriorityDecrement 0
*** ERROR: Module load completed but symbols could not be loaded for SomeDrv.sys
ChildEBP RetAddr
f4924640 80972e8e nt!SePrivilegeCheck+0x24
f4924678 80944aa0 nt!SeSinglePrivilegeCheck+0x3a
f4924770 8088978c nt!NtOpenProcess+0x13a
f4924770 8082eff5 nt!KiFastCallEntry+0xfc
f49247f8 f6037bee nt!ZwOpenProcess+0x11
WARNING: Stack unwind information not available. Following frames may be wrong.
f4924830 f6002996 SomeDrv+0x48bee
5: kd> !thread 86ffe700 1f
THREAD 86ffe700 Cid 1ba4.1ba8 Teb: 7ffdf000 Win32Thread: bc23cea8 RUNNING on processor 4
Not impersonating
DeviceMap e44e9a40
Owning Process 87005708 Image: WINWORD.EXE
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 1547251 LargeStack
UserTime 00:01:00.750
KernelTime 00:00:45.265
*** ERROR: Symbol file could not be found. Defaulted to export symbols for WINWORD.EXE -
Win32 Start Address WINWORD (0x300019b0)
Start Address kernel32!BaseProcessStartThunk (0x77e617f8)
Stack Init f3465000 Current f3464c48 Base f3465000 Limit f345e000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f3464d64 7c8285eb nt!KiFastCallEntry+0x91
f3464d68 badb0d00 ntdll!KiFastSystemCall+0x3
5: kd> !thread 86803a90 1f
THREAD 86803a90 Cid 3c20.29f8 Teb: 7ffdf000 Win32Thread: bc295480 RUNNING on processor 5
Not impersonating
DeviceMap e518c6b8
Owning Process 857d5500 Image: SystemDump.exe
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 310 LargeStack
UserTime 00:00:00.015
KernelTime 00:00:00.046
*** ERROR: Module load completed but symbols could not be loaded for SystemDump.exe
Win32 Start Address SystemDump_400000 (0x0040fe92)
Start Address kernel32!BaseProcessStartThunk (0x77e617f8)
Stack Init b38a4000 Current b38a3c08 Base b38a4000 Limit b389f000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 2
ChildEBP RetAddr Args to Child
b38a3bf0 f79e3743 000000e2 cccccccc 866962b0 nt!KeBugCheckEx+0x1b
WARNING: Stack unwind information not available. Following frames may be wrong.
b38a3c3c 8081df65 865c4460 870888c0 85a7ff90 SystemDump+0x743
b38a3c50 808f5437 87088930 85a7ff90 870888c0 nt!IofCallDriver+0x45
b38a3c64 808f61bf 865c4460 870888c0 85a7ff90 nt!IopSynchronousServiceTail+0x10b
b38a3d00 808eed08 000000e4 00000000 00000000 nt!IopXxxControlFile+0x5e5
b38a3d34 8088978c 000000e4 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
b38a3d34 7c8285ec 000000e4 00000000 00000000 nt!KiFastCallEntry+0xfc
0012efc4 7c826fcb 77e416f5 000000e4 00000000 ntdll!KiFastSystemCallRet
0012efc8 77e416f5 000000e4 00000000 00000000 ntdll!NtDeviceIoControlFile+0xc
0012f02c 00402208 000000e4 9c400004 00a37b38 kernel32!DeviceIoControl+0x137
0012f884 00404f8e 0012fe80 00000001 00000000 SystemDump_400000+0x2208
5: kd> !thread 86043db0 1f
THREAD 86043db0 Cid 0610.55dc Teb: 7ffa1000 Win32Thread: 00000000 RUNNING on processor 6
IRP List:
86dc99a0: (0006,0094) Flags: 00000a00 Mdl: 00000000
Impersonation token: e7b30030 (Level Impersonation)
DeviceMap e4e470a8
Owning Process 891374a8 Image: SomeSvc.exe
Wait Start TickCount 1415215 Ticks: 320 (0:00:00:05.000)
Context Switch Count 11728
UserTime 00:00:02.546
KernelTime 00:02:57.765
Win32 Start Address 0x0082b983
LPC Server thread working on message Id 82b983
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b49c1000 Current b49c0a7c Base b49c1000 Limit b49be000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
b49c0b80 8087c9c0 hal!KeReleaseQueuedSpinLock+0x2d
b49c0ba0 8087ca95 nt!ExReleaseResourceLite+0xac
b49c0ba4 f6faa5ae nt!ExReleaseResourceAndLeaveCriticalRegion+0x5
b49c0bb8 f6faad05 termdd!_IcaCallStack+0x60
b49c0bdc f6fa6bda termdd!IcaCallDriver+0x71
b49c0c34 f6fa86dc termdd!IcaWriteChannel+0xd8
b49c0c50 f6fa8cc6 termdd!IcaWrite+0x40
b49c0c68 8081df65 termdd!IcaDispatch+0xd0
b49c0c7c 808f5437 nt!IofCallDriver+0x45
b49c0c90 808f3157 nt!IopSynchronousServiceTail+0x10b
b49c0d38 8088978c nt!NtWriteFile+0x663
b49c0d38 7c8285ec nt!KiFastCallEntry+0xfc
0254d814 7c827d3b ntdll!KiFastSystemCallRet
0254d818 77e5b012 ntdll!NtWriteFile+0xc
0254d878 004389f2 kernel32!WriteFile+0xa9
5: kd> !thread 86bcbdb0 1f
THREAD 86bcbdb0 Cid 34ac.1b04 Teb: 7ffdd000 Win32Thread: bc3d9a48 RUNNING on processor 7
IRP List:
8581d900: (0006,01fc) Flags: 00000884 Mdl: 00000000
Not impersonating
DeviceMap e153fc48
Owning Process 872fb708 Image: SomeExe.exe
Wait Start TickCount 1415535 Ticks: 0
Context Switch Count 7655285 LargeStack
UserTime 00:10:09.343
KernelTime 00:30:21.296
Win32 Start Address 0x75ec1c3f
Start Address 0x77e617ec
Stack Init b86cb000 Current b86ca58c Base b86cb000 Limit b86c2000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
b86ca974 f724ffc2 fltmgr!FltpPerformPostCallbacks+0x260
b86ca988 f72504f1 fltmgr!FltpProcessIoCompletion+0x10
b86ca998 f7250b83 fltmgr!FltpPassThroughCompletion+0x89
b86ca9c8 f725e5de fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x269
b86caa04 8081df65 fltmgr!FltpCreate+0x26a
b86caa18 f75fa8c7 nt!IofCallDriver+0x45
b86caa40 f75faa5a SomeFlt!PassThrough+0xbb
b86caa5c 8081df65 SomeFlt!Create+0xda
b86caa70 808f8f71 nt!IofCallDriver+0x45
b86cab58 80937942 nt!IopParseDevice+0xa35
b86cabd8 80933a76 nt!ObpLookupObjectName+0x5b0
b86cac2c 808eae25 nt!ObOpenObjectByName+0xea
b86caca8 808ec0bf nt!IopCreateFile+0x447
b86cad04 808efc4f nt!IoCreateFile+0xa3
b86cad44 8088978c nt!NtOpenFile+0x27
b86cad44 7c8285ec nt!KiFastCallEntry+0xfc
Running threads have good chance to be Spiking Threads.
- Dmitry Vostokov @ DumpAnalysis.org -