Busy system, blocked threads, wait chains and deadlock: pattern cooperation
In one kernel memory dump we can see the signs of a busy system where all processors are executing non-idle threads:
0: kd> !running
System Processors ff (affinity mask)
Idle Processors 0
Prcb Current Next
0 ffdff120 8b223928 ................
1 f772f120 8a765380 ................
2 f7737120 89365db0 ................
3 f773f120 8833adb0 ................
4 f7747120 889bbdb0 ................
5 f774f120 8c085db0 ................
6 f7757120 8aa79698 ................
7 f775f120 896c0668 ................
When inspecting them we see that some are kernel worker threads without a process context, for example:
0: kd> !thread 8aa79698 1f
THREAD 8aa79698 Cid 0004.6edc Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 6
Not impersonating
DeviceMap d66008d0
Owning Process 8d15d648 Image: System
Wait Start TickCount 2548878 Ticks: 3 (0:00:00:00.046)
Context Switch Count 248713
UserTime 00:00:00.000
KernelTime 00:00:00.906
Start Address nt!ExpWorkerThread (0×80881860)
Stack Init acfbc000 Current acfbbcec Base acfbc000 Limit acfb9000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong.
acfbbaec b19483f3 driver+0×3f65
acfbbb6c 8081e095 driver+0×23f3
acfbbb80 af36044a nt!IofCallDriver+0×45
[…]
acfbbdac 8094bea4 nt!ExpWorkerThread+0xeb
acfbbddc 8088f57e nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16
some threads with an associated process context are running in kernel space:
0: kd> !thread 889bbdb0 1f
THREAD 889bbdb0 Cid 6c58.6f98 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 4
Not impersonating
DeviceMap d66008d0
Owning Process 89ad8b18 Image: csrss.exe
Wait Start TickCount 2548880 Ticks: 1 (0:00:00:00.015)
Context Switch Count 129536
UserTime 00:00:00.000
KernelTime 00:00:00.312
Start Address displaydriver!Thread (0xbfad4a60)
Stack Init a439d000 Current a439cc70 Base a439d000 Limit a439a000 Call 0
Priority 13 BasePriority 10 PriorityDecrement 3
ChildEBP RetAddr
a439c004 bfad707f displaydriver!CalcRegion+0×30
[…]
a439cddc 8088f57e nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16
and some threads with an associated process context are running in user space:
0: kd> !thread 8c085db0 1f
THREAD 8c085db0 Cid 2318.231c Teb: 7ffdd000 Win32Thread: b4b5ebe8 RUNNING on processor 5
Not impersonating
DeviceMap dc1a71f0
Owning Process 8b02e458 Image: Application.EXE
Wait Start TickCount 2548881 Ticks: 0
Context Switch Count 725122 LargeStack
UserTime 00:00:01.625
KernelTime 00:00:03.062
Win32 Start Address 0×30001084
Start Address 0×7c8217f8
Stack Init ad648000 Current ad647c50 Base ad648000 Limit ad642000 Call 0
Priority 12 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
0013fb7c 00000000 0×7c81b910
Because none of them consumed much CPU the patter of Spiking Thread is ruled out and CPU load can be explained by the number of active user sessions and this appears to be normal:
0: kd> !session
Sessions on machine: 50
However looking at ERESOURCE locks we see many blocked threads and signs of possible wait chains:
0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
Resource @ 0x8cbfaa68 Exclusively owned
Contention Count = 22969
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 109
Threads: 8a961db0-01<*> 8bf532b0-01
Threads Waiting On Exclusive Access:
8b4532f0 884fc648 88c58a00 8a751360
88ed64f8 89aa6738 89870db0 881dedb0
8a6d7b40 8b4a4db0 89818ad0 8afcedb0
8a2ca020 88684db0 8b411020 89d595c0
8d1573f0 88d06020 8aed8b38 8a8c9020
8a5a0a50 8a1f63b0 89b66688 89bf1db0
880dab18 882e6730 895d8020 88e6d3f0
896e6748 89802100 8a604508 8907c5e8
8890a020 885e2300 8a061bd8 88445340
88113db0 8a680db0 89b53370 88c3f2a0
88a774f8 8834ddb0 89d78888 88386020
897ca8d8 8b3532d0 882341d0 8a4a9b80
87e7c4f8 895e5db0 8846f4e8 89df3db0
889b8b40 89d82db0 89e4b720 8aadadb0
8aa63020 88852020 8a249ba8 891b8c20
8b3f95f0 8aace760 8b470020 897ad388
8c07dba8 8a331628 896c74d0 8997cb40
88e133c8 886eddb0 8864e518 89ab5698
88d8bdb0 89996db0 8ac54d28 87f42020
882b1020 8857fdb0 895f3db0 88b0ab40
8a1aadb0 8b819020 8b3bf388 88315660
8a45db18 883fbdb0 88f53db0 87f209a0
8978ddb0 8840c868 8823c1c8 88277db0
89c0a8c8 88322940 8a475db0 8a6ad460
8a35a4c8 88e3da40 886b1b40 8886a2a0
8897d750 8b30bdb0 8a123020 8b0ad7f8
8a256930 885cedb0 88ec8db0 887d7ba8
88175b90
Resource @ 0x8b8f09a8 Shared 1 owning threads
Contention Count = 123597
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 6
Threads: 88200840-01 8a92ddb0-01<*>
Threads Waiting On Exclusive Access:
8a317db0 8d151840 899acdb0 8a961db0
891ac940 89ee5db0
Resource @ 0x8ac79f08 Exclusively owned
Contention Count = 717691
NumberOfExclusiveWaiters = 12
Threads: 8a5193f0-01<*>
Threads Waiting On Exclusive Access:
880e7b40 8a60adb0 8a543108 8a4be020
8a77c360 8a470730 87f12db0 8a4618d0
895c5600 8a942b98 8a453b40 8a3bf020
Resource @ 0x8a73ed28 Exclusively owned
Contention Count = 4
NumberOfExclusiveWaiters = 2
Threads: 8a45db18-01<*>
Threads Waiting On Exclusive Access:
8a412db0 8a542268
Resource @ 0x8a621bf8 Exclusively owned
Contention Count = 8532
NumberOfExclusiveWaiters = 3
Threads: 8a412db0-01<*>
Threads Waiting On Exclusive Access:
8a5193f0 8a60cdb0 8a595c78
Resource @ 0x8a4c8b20 Exclusively owned
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: 8a92ddb0-01<*>
Threads Waiting On Exclusive Access:
89524a70
Resource @ 0x8a43b0e8 Exclusively owned
Contention Count = 1135854
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 9
Threads: 8aaa3020-01<*> 88efb400-01
Threads Waiting On Exclusive Access:
89f883b0 8a273a70 89f82c10 89fd9020
89ec0db0 89571290 89edcdb0 88930400
8845f4c8
Resource @ 0x89f7dbe8 Exclusively owned
Contention Count = 2
NumberOfExclusiveWaiters = 2
Threads: 891b8c20-01<*>
Threads Waiting On Exclusive Access:
89ecedb0 89fc3020
Resource @ 0x89f82f28 Exclusively owned
Contention Count = 26674
NumberOfExclusiveWaiters = 2
Threads: 89fc3020-01<*>
Threads Waiting On Exclusive Access:
8aaa3020 8a02db40
Resource @ 0x89315320 Exclusively owned
Contention Count = 509247
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 19
Threads: 89261428-01<*> 89313a08-01
Threads Waiting On Exclusive Access:
89cc7db0 8ad26528 8970db68 88ef64d0
8a629020 89450798 8825c9a8 89206378
8a7c7b90 89162890 8ae7c020 883318e0
88bd6358 89367db0 8952aaa0 8a817b40
881d65b8 8ab74db0 889202c0
Resource @ 0x893872d8 Exclusively owned
Contention Count = 5079
NumberOfExclusiveWaiters = 3
Threads: 896e6748-01<*>
Threads Waiting On Exclusive Access:
89261428 893bc3c8 892a88a8
Resource @ 0x8924adf8 Exclusively owned
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: 88ed64f8-01<*>
Threads Waiting On Exclusive Access:
89146660
Resource @ 0x890281b0 Exclusively owned
Contention Count = 4
NumberOfExclusiveWaiters = 4
Threads: 88d06020-01<*>
Threads Waiting On Exclusive Access:
88b5c528 88c5aa98 87ef77b8 88c48b40
Resource @ 0x88d40440 Exclusively owned
Contention Count = 13
NumberOfExclusiveWaiters = 1
Threads: 899acdb0-01<*>
Threads Waiting On Exclusive Access:
895e6db0
Resource @ 0x88ed0c20 Exclusively owned
Contention Count = 2
NumberOfExclusiveWaiters = 2
Threads: 895e6db0-01<*>
Threads Waiting On Exclusive Access:
88ad7540 88b5f620
Resource @ 0x894e7990 Exclusively owned
Contention Count = 3852647
NumberOfExclusiveWaiters = 12
Threads: 881b14b8-01<*>
Threads Waiting On Exclusive Access:
88a13db0 87f12020 8aad7a20 8820a020
8824bdb0 88213db0 88eefdb0 88ab7550
889fe808 89df17a0 8aa83430 8a8f73c8
Resource @ 0x88559288 Exclusively owned
Contention Count = 7422
NumberOfExclusiveWaiters = 3
Threads: 880dab18-01<*>
Threads Waiting On Exclusive Access:
881b14b8 88311020 882ab660
Resource @ 0x8aff12b0 Exclusively owned
Contention Count = 6
NumberOfExclusiveWaiters = 1
Threads: 89524a70-01<*>
Threads Waiting On Exclusive Access:
8a92ddb0
62174 total locks, 75 locks currently held
Starting with the thread 8a961db0 that blocks 109 other threads we can unravel the following deadlock:
109 threads -> 8a961db0 -> 8a92ddb0 -> 89524a70 -> 8a92ddb0 -> 89524a70 -> …
Looking at threads involved in the deadlock we see that they belong to the same process and deadlocked in kernel space when running through driverA.sys code:
0: kd> !thread 89524a70 1f
THREAD 89524a70 Cid 1fdc.26cc Teb: 7ffdd000 Win32Thread: b4d0fea8 WAIT: (Unknown) KernelMode Non-Alertable
89170648 SynchronizationEvent
89524ae8 NotificationTimer
IRP List:
88e7a008: (0006,0268) Flags: 00000000 Mdl: 00000000
8a7cc228: (0006,0268) Flags: 00000000 Mdl: 00000000
89e67b90: (0006,0268) Flags: 00000000 Mdl: 00000000 Not impersonating
DeviceMap e2e671d0
Owning Process 88c37020 Image: ApplicationA.exe
Wait Start TickCount 2548760 Ticks: 121 (0:00:00:01.890)
Context Switch Count 4850 LargeStack
UserTime 00:00:00.734
KernelTime 00:00:01.718
Win32 Start Address 0×00404054
Start Address 0×7c8217f8
Stack Init 91971000 Current 91970278 Base 91971000 Limit 9196a000 Call 0
Priority 14 BasePriority 10 PriorityDecrement 4
ChildEBP RetAddr
91970290 80833ec5 nt!KiSwapContext+0×26
919702bc 80829bc0 nt!KiSwapThread+0×2e5
91970304 8087e0db nt!KeWaitForSingleObject+0×346
91970340 8087e2f5 nt!ExpWaitForResource+0xd5
91970360 b0a1cf6d nt!ExAcquireResourceExclusiveLite+0×8d
91970374 b0a08cef driverA+0×2ef6d
919703cc b0a089cc driverA+0×1acef
919703f4 b0a209d9 driverA+0×1a9cc
9197056c b0a20386 driverA+0×329d9
91970630 b0a1dc32 driverA+0×32386
919706e8 b0a20508 driverA+0×2fc32
919707ac b0a1eec1 driverA+0×32508
919708a0 b0a21e90 driverA+0×30ec1
91970930 b0a171c9 driverA+0×33e90
919709c4 b0a16c9d driverA+0×291c9
91970a38 b0a600b3 driverA+0×28c9d
91970a84 b0a45dda driverA+0×720b3
91970afc b0a4657a driverA+0×57dda
91970b48 8081e095 driverA+0×5857a
91970b5c f7876d28 nt!IofCallDriver+0×45
91970b88 8081e095 fltmgr!FltpDispatch+0×152
91970b9c f74fc6ca nt!IofCallDriver+0×45
91970bb4 f7876d28 driverB+0×56ca
91970be0 8081e095 fltmgr!FltpDispatch+0×152
91970bf4 b195a4e1 nt!IofCallDriver+0×45
91970c18 b195a5d0 driverC!PassThrough+0xd1
91970c28 8081e095 driverC!Dispatch+0×80
91970c3c f7876d28 nt!IofCallDriver+0×45
91970c68 8081e095 fltmgr!FltpDispatch+0×152
91970c7c 808f7601 nt!IofCallDriver+0×45
91970c90 808f5339 nt!IopSynchronousServiceTail+0×10b
91970d38 8088ac9c nt!NtWriteFile+0×663
91970d38 7c9485ec nt!KiFastCallEntry+0xfc
0: kd> !thread 8a92ddb0 1f
THREAD 8a92ddb0 Cid 1fdc.7b98 Teb: 7ffa9000 Win32Thread: b4deeae8 WAIT: (Unknown) KernelMode Non-Alertable
8b422388 SynchronizationEvent
8a92de28 NotificationTimer
Not impersonating
DeviceMap e2e671d0
Owning Process 88c37020 Image: ApplicationA.exe
Wait Start TickCount 2548760 Ticks: 121 (0:00:00:01.890)
Context Switch Count 956 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.015
Win32 Start Address 0×01381fa0
Start Address 0×7c8217ec
Stack Init 917c1000 Current 917c034c Base 917c1000 Limit 917bd000 Call 0
Priority 14 BasePriority 10 PriorityDecrement 4
ChildEBP RetAddr
917c0364 80833ec5 nt!KiSwapContext+0×26
917c0390 80829bc0 nt!KiSwapThread+0×2e5
917c03d8 8087e0db nt!KeWaitForSingleObject+0×346
917c0414 8087e2f5 nt!ExpWaitForResource+0xd5
917c0434 b0a1cf6d nt!ExAcquireResourceExclusiveLite+0×8d
917c0448 b0a08cef driverA+0×2ef6d
917c04a0 b0a089cc driverA+0×1acef
917c04c8 b0a13787 driverA+0×1a9cc
917c053c b0a0bfaa driverA+0×25787
917c057c b0a0c3b3 driverA+0×1dfaa
917c0858 b0a0ccaf driverA+0×1e3b3
917c0934 b0a6074c driverA+0×1ecaf
917c097c b0a4f9d2 driverA+0×7274c
917c0a18 b0a501f6 driverA+0×619d2
917c0a40 b0a5020c driverA+0×621f6
917c0a4c b0a50442 driverA+0×6220c
917c0a6c b0a50687 driverA+0×62442
917c0ac4 b0a50cb0 driverA+0×62687
917c0b08 b0a50ddd driverA+0×62cb0
917c0b18 8081e095 driverA+0×62ddd
917c0b2c f7876d28 nt!IofCallDriver+0×45
917c0b58 8081e095 fltmgr!FltpDispatch+0×152
917c0b6c f74fc6ca nt!IofCallDriver+0×45
917c0b84 f7876d28 driverB+0×56ca
917c0bb0 8081e095 fltmgr!FltpDispatch+0×152
917c0bc4 b195a4e1 nt!IofCallDriver+0×45
917c0be8 b195a5d0 driverC!PassThrough+0xd1
917c0bf8 8081e095 driverC!Dispatch+0×80
917c0c0c f7876d28 nt!IofCallDriver+0×45
917c0c38 8081e095 fltmgr!FltpDispatch+0×152
917c0c4c 808f7601 nt!IofCallDriver+0×45
917c0c60 808f1b45 nt!IopSynchronousServiceTail+0×10b
917c0c84 afdfebd5 nt!NtQueryDirectoryFile+0×5d
917c0cf8 afdff95d driverD+0×8bd5
917c0d30 8088ac9c driverD+0×995d
917c0d30 7c9485ec nt!KiFastCallEntry+0xfc
Other wait chains seem to be subordinate to the main deadlock chain.
- Dmitry Vostokov @ DumpAnalysis.org -