Archive for January 8th, 2011

Crash Dump Analysis Patterns (Part 126)

Saturday, January 8th, 2011

Finally I got a few good crash dumps illustrating Livelock pattern when 2 threads are looping while acquiring and releasing a resource but not progressing. We have these signs in selected WinDbg output below:

- high contention patterns or context switch counts

- increased CPU time in user and / or kernel mode

- at least one livelocked thread is scheduled for execution

- one of livelocked threads has unusual priority boost

- the same thread stack trace for both livelocked threads having similar stats like spent time and context switch counts

- zero waiting ticks

1: kd> !locks

Resource @ 0xfffffa8008464528    Exclusively owned
    Contention Count = 43743004
    NumberOfExclusiveWaiters = 1
     Threads: fffffa8008315b60-01<*>
     Threads Waiting On Exclusive Access:
              fffffa8005769660

41080 total locks, 1 locks currently held

1: kd> !running

Prcbs  Current           Next            
  1    fffff88001e68180  fffff88001e72fc0  fffffa8008315b60  …………….

We have these stack traces from stack trace collection:

THREAD fffffa8008315b60  Cid 0724.2a28  Teb: 000007fffff9c000 Win32Thread: 0000000000000000 ????
IRP List:
    fffffa80082e5990: (0006,0118) Flags: 00060000  Mdl: 00000000
Not impersonating
DeviceMap                 fffff8a009f434e0
Owning Process            fffffa8005726360       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      522197         Ticks: 0
Context Switch Count      21665144           
UserTime                  00:00:40.373
KernelTime                00:02:42.791
Win32 Start Address 0×000007fef6939430
Stack Init fffff88007321db0 Current fffff88007321520
Base fffff88007322000 Limit fffff8800731c000 Call 0
Priority 8 BasePriority 6 UnusualBoost 1 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff880`07321560 fffff800`0168a992 nt!KiSwapContext+0×7a
fffff880`073216a0 fffff800`0168ccff nt!KiCommitThreadWait+0×1d2
fffff880`07321730 fffff800`0164c242 nt!KeWaitForSingleObject+0×19f
fffff880`073217d0 fffff800`0168b5ac nt!ExpWaitForResource+0xae
fffff880`07321840 fffff880`04608d91 nt!ExAcquireResourceExclusiveLite+0×14f
fffff880`073218b0 fffff880`04609e4e DriverA!foo+0×42
[…]
fffff880`07321a10 fffff800`0199ef66 nt!IopXxxControlFile+0×607
fffff880`07321b40 fffff800`01682993 nt!NtDeviceIoControlFile+0×56
fffff880`07321bb0 00000000`76ffff2a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`07321c20)
00000000`03a1f488 000007fe`fd06b399 ntdll!NtDeviceIoControlFile+0xa
00000000`03a1f490 00000000`76ea610f KERNELBASE!DeviceIoControl+0×75
00000000`03a1f500 000007fe`f74f3d7c kernel32!DeviceIoControlImplementation+0×7f
[…]

THREAD fffffa8005769660  Cid 0724.10b0  Teb: 000007fffffa6000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
    fffffa8006661f20  SynchronizationEvent
IRP List:
    fffffa8006b1ac10: (0006,0118) Flags: 00060000  Mdl: 00000000
Not impersonating
DeviceMap                 fffff8a009f434e0
Owning Process            fffffa8005726360       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      522197         Ticks: 0
Context Switch Count      21601988           
UserTime                  00:00:30.147
KernelTime                00:02:30.972
Win32 Start Address 0×000007fef6939430
Stack Init fffff880071bbdb0 Current fffff880071bb520
Base fffff880071bc000 Limit fffff880071b6000 Call 0
Priority 7 BasePriority 6 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff880`071bb560 fffff800`0168a992 nt!KiSwapContext+0×7a
fffff880`071bb6a0 fffff800`0168ccff nt!KiCommitThreadWait+0×1d2
fffff880`071bb730 fffff800`0164c242 nt!KeWaitForSingleObject+0×19f
fffff880`071bb7d0 fffff800`0168b5ac nt!ExpWaitForResource+0xae
fffff880`071bb840 fffff880`04608d91 nt!ExAcquireResourceExclusiveLite+0×14f
fffff880`071bb8b0 fffff880`04609e4e DriverA!foo+0×42
[…]
fffff880`071bba10 fffff800`0199ef66 nt!IopXxxControlFile+0×607
fffff880`071bbb40 fffff800`01682993 nt!NtDeviceIoControlFile+0×56
fffff880`071bbbb0 00000000`76ffff2a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`071bbc20)
00000000`033bf708 000007fe`fd06b399 ntdll!NtDeviceIoControlFile+0xa
00000000`033bf710 00000000`76ea610f KERNELBASE!DeviceIoControl+0×75
00000000`033bf780 000007fe`f74f3d7c kernel32!DeviceIoControlImplementation+0×7f
[…]

In both traces we have DriverA as Blocking Module.

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | No Comments »