Crash Dump Analysis Patterns (Part 44)
Spiking Thread pattern includes normal threads running at PASSIVE_LEVEL or APC_LEVEL IRQL that can be preempted by any other higher priority thread. Therefore, spiking threads are not necessarily ones that were in RUNNING state when the memory dump was saved. They consumed much CPU and this is reflected in their User and Kernel time values. The pattern also includes threads running at DISPATCH_LEVEL and higher IRQL. These threads cannot be preempted by another thread so they usually remain in RUNNING state all the time unless they lower their IRQL. Some of them I’ve seen were trying to acquire a spinlock and I decided to create another more specialized pattern and call it Dispatch Level Spin. We would see it when a spinlock for some data structure wasn’t released or was corrupt and some thread tries to acquire it and enters endless spinning loop unless interrupted by higher IRQL interrupt. These infinite loops can also happen due to software defects in code running at dispatch level or higher IRQL.
Let’s look at one example. The following running thread was interrupted by keyboard interrupt apparently to save Manual Dump. We see that it spent almost 11 minutes in kernel:
0: kd> !thread
THREAD 830c07c0 Cid 0588.0528 Teb: 7ffa3000 Win32Thread: e29546a8 RUNNING on processor 0
IRP List:
86163008: (0006,01d8) Flags: 00000900 Mdl: 84f156c0
Not impersonating
DeviceMap e257b7c8
Owning Process 831ec608 Image: MyApp.EXE
Wait Start TickCount 122850 Ticks: 40796 (0:00:10:37.437)
Context Switch Count 191 LargeStack
UserTime 00:00:00.000
KernelTime 00:10:37.406
Win32 Start Address MyApp!ThreadImpersonation (0×35f76821)
Start Address kernel32!BaseThreadStartThunk (0×7c810659)
Stack Init a07bf000 Current a07beca0 Base a07bf000 Limit a07bb000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 2 DecrementCount 16
ChildEBP RetAddr
a07be0f8 f77777fa nt!KeBugCheckEx+0×1b
a07be114 f7777032 i8042prt!I8xProcessCrashDump+0×237
a07be15c 805448e5 i8042prt!I8042KeyboardInterruptService+0×21c
a07be15c 806e4a37 nt!KiInterruptDispatch+0×45 (FPO: [0,2] TrapFrame @ a07be180)
a07be220 a1342755 hal!KeAcquireInStackQueuedSpinLock+0×47
a07be220 a1342755 MyDriver!RcvData+0×98
…
…
…
To see the code and context we switch to the trap frame and disassemble the interrupted function:
1: kd> .trap a07be180
ErrCode = 00000000
eax=a07be200 ebx=a07be228 ecx=831dabf5 edx=a07beb94 esi=831d02a8 edi=831dabd8
eip=806e4a37 esp=a07be1f4 ebp=a07be220 iopl=0 nv up ei pl nz na po nc
cs=0008 ss=0010 ds=0000 es=0000 fs=0000 gs=0000 efl=00000202
hal!KeAcquireInStackQueuedSpinLock+0x47:
806e4a37 ebf3 jmp hal!KeAcquireInStackQueuedSpinLock+0×3c (806e4a2c)
1: kd> uf hal!KeAcquireInStackQueuedSpinLock
hal!KeAcquireInStackQueuedSpinLock:
806e49f0 mov eax,dword ptr ds:[FFFE0080h]
806e49f5 shr eax,4
806e49f8 mov al,byte ptr hal!HalpVectorToIRQL (806ef218)[eax]
806e49fe mov dword ptr ds:[0FFFE0080h],41h
806e4a08 mov byte ptr [edx+8],al
806e4a0b mov dword ptr [edx+4],ecx
806e4a0e mov dword ptr [edx],0
806e4a14 mov eax,edx
806e4a16 xchg edx,dword ptr [ecx]
806e4a18 cmp edx,0
806e4a1b jne hal!KeAcquireInStackQueuedSpinLock+0x34 (806e4a24)
hal!KeAcquireInStackQueuedSpinLock+0x2d:
806e4a1d or ecx,2
806e4a20 mov dword ptr [eax+4],ecx
hal!KeAcquireInStackQueuedSpinLock+0x33:
806e4a23 ret
hal!KeAcquireInStackQueuedSpinLock+0x34:
806e4a24 or ecx,1
806e4a27 mov dword ptr [eax+4],ecx
806e4a2a mov dword ptr [edx],eax
hal!KeAcquireInStackQueuedSpinLock+0x3c:
806e4a2c test dword ptr [eax+4],1
806e4a33 je hal!KeAcquireInStackQueuedSpinLock+0×33 (806e4a23)
hal!KeAcquireInStackQueuedSpinLock+0x45:
806e4a35 pause
806e4a37 jmp hal!KeAcquireInStackQueuedSpinLock+0×3c (806e4a2c)
JMP instruction transfers execution to the code that tests the first bit at [EAX+4] address. If it isn’t set it falls through to the same JMP instruction. We know the value of EAX from the trap frame so we can dereference that address:
1: kd> dyd eax+4 l1
3 2 1 0
10987654 32109876 54321098 76543210
-------- -------- -------- --------
a07be204 10000011 00011101 10101011 11110101 831dabf5
The value is odd: the first leftmost bit is set. Therefore the code will loop indefinitely unless a different thread running on another processor clears that bit. However the second processor is idle:
0: kd> ~0s
0: kd> k
ChildEBP RetAddr
f794cd54 00000000 nt!KiIdleLoop+0x14
Seems we have a problem. We need to examine MyDriver.sys code to understand how it uses queued spinlocks.
Note: In addition to user-defined there are internal system queued spinlocks you can check by using !qlocks WinDbg command.
- Dmitry Vostokov @ DumpAnalysis.org -
June 27th, 2008 at 1:13 am
[…] higher priority thread (Thread Starvation pattern) or loops at dispatch level IRQL (Dispatch Level Spin pattern). Therefore I call this pattern Affine […]
January 18th, 2009 at 11:48 pm
[…] and blocks threads (pp. 63 - 64) - See my real life patterns Dispatch Level Spin and Affine Thread http://www.dumpanalysis.org/blog/index.php/2008/01/25/crash-dump-analysis-patterns-part-44/ and […]
September 28th, 2010 at 2:59 pm
[…] Experts Magazine Online Today we introduce an icon for Dispatch Level Spin […]