Wait chain, blocked thread, waiting thread time, IRP distribution anomaly and stack trace collection: pattern cooperation

A kernel dump from a frozen system shows an executive resource wait chain:

0: kd> !locks
[...] 
Resource @ driverA!Resource (0xf58de4e0)    Exclusively owned
    Contention Count = 4411
    NumberOfExclusiveWaiters = 11
     Threads: 86d14ae8-01<*>
     Threads Waiting On Exclusive Access:
              8a788db0       8750e970       86c568a0       897ed428      
              86e34db0       86ca8ac0       86b22020       86fef5d8      
              872abdb0       86d16750       87b55830      
[…]

The blocking thread 86d14ae8 had been blocked waiting for a notification event for more than 2 hours:

0: kd> !thread 86d14ae8 1f
THREAD 86d14ae8  Cid 0004.29c4  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    b81e7adc  NotificationEvent
Not impersonating
DeviceMap                 e1001830
Owning Process            8a78b020       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      8378144        Ticks: 503606 (0:02:11:08.843)
Context Switch Count      1016            
UserTime                  00:00:00.000
KernelTime                00:00:00.015
Start Address driverA!WorkerThreadDispatcher (0xf596ea0e)
Stack Init b81e8000 Current b81e7a2c Base b81e8000 Limit b81e5000 Call 0
Priority 14 BasePriority 10 PriorityDecrement 4
ChildEBP RetAddr 
b81e7a44 8083d5b1 nt!KiSwapContext+0×26
b81e7a70 8083df9e nt!KiSwapThread+0×2e5
b81e7ab8 f59d374d nt!KeWaitForSingleObject+0×346
[…]
b81e7b48 f59b9289 driverB!TcpDisconnect+0×42
[…]
b81e7c40 f595a8a5 nt!IofCallDriver+0×45
b81e7c48 f595ba1e driverA!SubmitTdiRequestNoWait+0×28
[…]
b81e7dac 80920833 driverA!WorkerThreadDispatcher+0×1a
b81e7ddc 8083fe9f nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

We see that the wait happens after requesting a TCP disconnect so we check the list of IRP to see if there is any distribution anomaly among pending IRP:

0: kd> !irpfind
  Irp    [ Thread ] irpStack: (Mj,Mn)   DevObj  [Driver]         MDL Process
[...]
86c68d98 [88d2bdb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c6a5c0 [89b118c0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c6b008 [87564b40] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c6caf0 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c7bb28 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c7bd98 [8753ddb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c80008 [88d7b378] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c80590 [88e1c368] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c845a8 [89d2b400] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c84b80 [88d7b378] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c86008 [88e1c368] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c86688 [86d9a788] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c86d98 [88d2bdb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c87990 [88e1c368] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c8b640 [8757c3f0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c8f368 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c8f650 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c92590 [87625c30] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c92bc8 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c94008 [8757c3f0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c94318 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c9a308 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c9e008 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86c9e308 [89d2b400] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca0350 [87638020] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca0870 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca0b28 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca0d98 [86db0db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca4918 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86ca6878 [87564b40] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86caa458 [88d7b378] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86cacc20 [86d4fb40] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86cb0818 [89c75bb0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86cb3658 [87638020] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]
86cb9d98 [88d66db0] irpStack: ( f, 6)  89cb5ea8 [ \Driver\Tcpip]

[…]

Indeed, we see a high disproportion of TCP I/O requests (many hundreds) after exporting command output to Excel:

We check all stack traces and see one system thread trying to clean TCP connection blocked for almost the same time (more than 2 hours):

0: kd> !stacks
Proc.Thread  .Thread  Ticks   ThreadState Blocker
                            [8a78b020 System]
[...]
   4.00268c  870cf768 00765bd Blocked    tcpip!TCPCleanup+0xcf
[…]

0: kd> !whattime  00765bd
484797 Ticks in Standard Time:   2:06:14.953s

0: kd> !thread 870cf768 1f
THREAD 870cf768  Cid 0004.268c  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    870a01f4  SynchronizationEvent
IRP List:
    8726fb00: (0006,0268) Flags: 00000404  Mdl: 00000000
Not impersonating
DeviceMap                 e1001830
Owning Process            8a78b020       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      8396953        Ticks: 484797 (0:02:06:14.953)
Context Switch Count      537            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address nt!ExpWorkerThread (0×8082da4b)
Stack Init b87b0000 Current b87afa18 Base b87b0000 Limit b87ad000 Call 0
Priority 15 BasePriority 15 PriorityDecrement 0
ChildEBP RetAddr 
b87afa30 8083d5b1 nt!KiSwapContext+0×26
b87afa5c 8083df9e nt!KiSwapThread+0×2e5
b87afaa4 f5a9f9a6 nt!KeWaitForSingleObject+0×346
b87afaf0 f5a96a9d tcpip!TCPCleanup+0xcf
b87afb2c 80840153 tcpip!TCPDispatch+0×10c

b87afb40 f75eb817 nt!IofCallDriver+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
b87afb64 f75e8698 driverC!DispatchPassThrough+0×4c
[…]
b87afbcc 8092ec0a nt!IofCallDriver+0×45
b87afbfc 8092b6af nt!IopCloseFile+0×2ae
b87afc2c 8092b852 nt!ObpDecrementHandleCount+0xcc
b87afc54 8092b776 nt!ObpCloseHandleTableEntry+0×131
b87afc98 8092b7c1 nt!ObpCloseHandle+0×82
b87afca8 80833bdf nt!NtClose+0×1b
b87afca8 8083b00c nt!KiFastCallEntry+0xfc (TrapFrame @ b87afcb4)
b87afd24 f59d3a3a nt!ZwClose+0×11
b87afd3c f59b78a1 driverB!TdiCloseConnection+0×38
[…]
b87afdac 80920833 nt!ExpWorkerThread+0xeb
b87afddc 8083fe9f nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

- Dmitry Vostokov @ DumpAnalysis.org -

Leave a Reply