Software Diagnostics Library

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 -

Completely mutated Richard Dawkins‘ quotation after listening to his latest book “The Greatest Show on Earth” and reading Fern Elsdon-Baker’s book “The Selfish Genius”:

“Memory dumps are facts”.

Dmitry Vostokov’s statement upon hearing “Evolution is a fact.”

No offence to Dawkins’ camp, watch out the publication of the next issue of Debugged! magazine about systematics and evolution of software defects:

Darwinian Debugging

- Dmitry Vostokov @ DumpAnalysis.org -

Previously announced Software Maintenance Institute was finally registered in Ireland (Reg. No. 400906) and its certificate was received yesterday.

Here is the current component structure of various institutions (depicted in UML):

Interface Tags:

IIP Interface of Iterative Publishing
IRD Interface of Research and Development
IDR Interface of Defect Research
IIR Interface of Information Repository
IME Interface of Memetic Engineering

- Dmitry Vostokov @ DumpAnalysis.org -