Insufficient memory, handle leak, process factory, high contention and busy system: pattern cooperation
It was reported that one system became slower and slower and eventually the complete memory dump was generated for analysis. Usual !vm 4 command shows pool allocation errors and particularly insufficient session pool memory for user session 1:
1: kd> !vm 4
*** Virtual Memory Usage ***
Physical Memory: 1048503 ( 4194012 Kb)
Page File: \??\C:\pagefile.sys
Current: 5109760 Kb Free Space: 3668764 Kb
Minimum: 5109760 Kb Maximum: 5109760 Kb
Available Pages: 409409 ( 1637636 Kb)
ResAvail Pages: 708135 ( 2832540 Kb)
Locked IO Pages: 108 ( 432 Kb)
Free System PTEs: 137566 ( 550264 Kb)
Free NP PTEs: 27288 ( 109152 Kb)
Free Special NP: 0 ( 0 Kb)
Modified Pages: 780 ( 3120 Kb)
Modified PF Pages: 771 ( 3084 Kb)
NonPagedPool Usage: 37587 ( 150348 Kb)
NonPagedPool Max: 65214 ( 260856 Kb)
PagedPool 0 Usage: 21583 ( 86332 Kb)
PagedPool 1 Usage: 3054 ( 12216 Kb)
PagedPool 2 Usage: 3076 ( 12304 Kb)
PagedPool 3 Usage: 3050 ( 12200 Kb)
PagedPool 4 Usage: 3040 ( 12160 Kb)
PagedPool Usage: 33803 ( 135212 Kb)
PagedPool Maximum: 66560 ( 266240 Kb)
********** 185454 pool allocations have failed **********
Shared Commit: 123289 ( 493156 Kb)
Special Pool: 0 ( 0 Kb)
Shared Process: 101937 ( 407748 Kb)
PagedPool Commit: 33850 ( 135400 Kb)
Driver Commit: 1697 ( 6788 Kb)
Committed pages: 1159581 ( 4638324 Kb)
Commit limit: 2283111 ( 9132444 Kb)
[...]
Session ID 1 @ af925000:
Paged Pool Usage: 16868K
*** 371034 Pool Allocation Failures ***
Commit Usage: 17960K
Session ID 2 @ af927000:
Paged Pool Usage: 2856K
Commit Usage: 3860K
[...]
The exploration of session 1 processes shows Process Factory pattern (5,000 launched processes) with explorer.exe ran amok:
1: kd> !sprocess 1
Dumping Session 1
_MM_SESSION_SPACE af925000
_MMSESSION af925d80
PROCESS 87db34a0 SessionId: 1 Cid: 4a68 Peb: 7ffd4000 ParentCid: 01b8
DirBase: cffb6d20 ObjectTable: e6084268 HandleCount: 11677.
Image: csrss.exe
PROCESS 86083020 SessionId: 1 Cid: 4560 Peb: 7ffde000 ParentCid: 2978
DirBase: cffb6f40 ObjectTable: e6c41410 HandleCount: 79.
Image: AnotherApp.exe
PROCESS 8607c020 SessionId: 1 Cid: 44c8 Peb: 7ffdc000 ParentCid: 4cf8
DirBase: cffb7080 ObjectTable: e3c9fd38 HandleCount: 25407.
Image: explorer.exe
[...]
PROCESS 85e94738 SessionId: 1 Cid: 4868 Peb: 7ffde000 ParentCid: 44c8
DirBase: cffb7c00 ObjectTable: e7038840 HandleCount: 39.
Image: application.exe
PROCESS 85e5c020 SessionId: 1 Cid: 4668 Peb: 7ffd4000 ParentCid: 4a50
DirBase: cffb7de0 ObjectTable: e11891d0 HandleCount: 172.
Image: application.exe
PROCESS 85e51578 SessionId: 1 Cid: 4c9c Peb: 7ffde000 ParentCid: 44c8
DirBase: cffb7e40 ObjectTable: e2ee0070 HandleCount: 39.
Image: application.exe
[...]
PROCESS 85c81020 SessionId: 1 Cid: 53a4 Peb: 7ffd7000 ParentCid: 44c8
DirBase: cffb89c0 ObjectTable: e6d2f600 HandleCount: 39.
Image: application.exe
PROCESS 85c6fb18 SessionId: 1 Cid: 53a8 Peb: 7ffd7000 ParentCid: 44c8
DirBase: cffb89e0 ObjectTable: e54df078 HandleCount: 39.
Image: application.exe
PROCESS 85c60020 SessionId: 1 Cid: 53bc Peb: 7ffdf000 ParentCid: 44c8
DirBase: cffb8a40 ObjectTable: e1214e90 HandleCount: 39.
Image: application.exe
[...]
We can also see the very big number of handles in both csrss.exe and explorer.exe. If we look at one of 5,000 application.exe processes we would see that it is a GUI application and this explains session pool exhaustion:
1: kd> !process 85c60020 1f
PROCESS 85c60020 SessionId: 1 Cid: 53bc Peb: 7ffdf000 ParentCid: 44c8
DirBase: cffb8a40 ObjectTable: e1214e90 HandleCount: 39.
Image: application.exe
VadRoot 85c97450 Vads 80 Clone 0 Private 173. Modified 159. Locked 0.
DeviceMap e3743340
Token e2ead5e0
ElapsedTime 00:54:17.218
UserTime 00:00:00.015
KernelTime 00:00:00.000
QuotaPoolUsage[PagedPool] 32460
QuotaPoolUsage[NonPagedPool] 3200
Working Set Sizes (now,min,max) (30, 50, 345) (120KB, 200KB, 1380KB)
PeakWorkingSetSize 778
VirtualSize 16 Mb
PeakVirtualSize 17 Mb
PageFaultCount 829
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 212
THREAD 85c25db0 Cid 53bc.5470 Teb: 7ffde000 Win32Thread: bd1a18a8 WAIT: (Unknown) UserMode Non-Alertable
85bbf2a8 SynchronizationEvent
Not impersonating
DeviceMap e3743340
Owning Process 85c60020 Image: application.exe
Wait Start TickCount 1121133 Ticks: 206877 (0:00:53:52.453)
Context Switch Count 19355 NoStackSwap LargeStack
UserTime 00:00:00.015
KernelTime 00:00:00.000
Win32 Start Address application (0x00402a38)
Start Address kernel32!BaseProcessStartThunk (0x7c8217f8)
Stack Init ad2b8000 Current ad2b7b1c Base ad2b8000 Limit ad2b4000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
ad2b7b34 80833ec5 nt!KiSwapContext+0x26
ad2b7b60 80829bc0 nt!KiSwapThread+0x2e5
ad2b7ba8 bf89aacc nt!KeWaitForSingleObject+0x346
ad2b7c04 bf8c4816 win32k!xxxSleepThread+0×1be
ad2b7ca0 bf8a134f win32k!xxxInterSendMsgEx+0×798
ad2b7cec bf85ae3c win32k!xxxSendMessageTimeout+0×1f3
ad2b7d10 bf8c13dc win32k!xxxWrapSendMessage+0×1b
ad2b7d40 8088ad3c win32k!NtUserMessageCall+0×9d
ad2b7d40 7c9485ec nt!KiFastCallEntry+0xfc (TrapFrame @ ad2b7d64)
0012f814 00000000 ntdll!KiFastSystemCallRet
We also see extremely high executive resource contention and various signs of a busy system like the fact that all processors are busy and very high number of ready threads at normal priority (about 1,000):
1: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
Resource @ DriverA (0xbae016a0) Exclusively owned
Contention Count = 277088870
NumberOfExclusiveWaiters = 3591
Threads: 83b46db0-01<*> << Too many exclusive waiters to list>>
1: kd> !running
System Processors ff (affinity mask)
Idle Processors 0
Prcb Current Next
0 ffdff120 86300b40 …………….
1 f772f120 f77320a0 852fadb0 …………….
2 f7737120 f773a0a0 861528d0 …………….
3 f773f120 f77420a0 877a4020 …………….
4 f7747120 f774a0a0 865909a8 …………….
5 f774f120 f77520a0 83d62cd0 …………….
6 f7757120 f775a0a0 841aa020 …………….
7 f775f120 f77620a0 ffb7b5e0 …………….
1: kd> !ready
Processor 0: No threads in READY state
Processor 1: Ready Threads at priority 10
THREAD 861b1898 Cid 4860.4894 Teb: 7ffd8000 Win32Thread: bc1669a8 READY
Processor 1: Ready Threads at priority 9
THREAD 83b46db0 Cid 44c8.a11c Teb: 7f8f8000 Win32Thread: bcbabb38 READY
Processor 1: Ready Threads at priority 8
THREAD 851408d0 Cid 6338.6398 Teb: 7ffdf000 Win32Thread: bc9bfbb8 READY
THREAD 83eb1730 Cid 8f30.9568 Teb: 7ffdf000 Win32Thread: 00000000 READY
THREAD fd310af8 Cid d53c.b4d8 Teb: 7ffdf000 Win32Thread: 00000000 READY
THREAD 83bce8d0 Cid abec.6450 Teb: 7ffdd000 Win32Thread: 00000000 READY
THREAD 83de2388 Cid a618.d79c Teb: 7ffde000 Win32Thread: 00000000 READY
THREAD 84197b40 Cid 44c8.6974 Teb: 7fe6a000 Win32Thread: bc662d48 READY
[…]
Processor 1: Ready Threads at priority 7
THREAD 86d0c890 Cid 3524.365c Teb: 7ff8e000 Win32Thread: bc403bb0 READY
Processor 2: No threads in READY state
Processor 3: No threads in READY state
Processor 4: No threads in READY state
Processor 5: No threads in READY state
Processor 6: No threads in READY state
Processor 7: No threads in READY state
There is AnotherApp.exe in the session process list that executes a VBS script:
1: kd> .process /r /p 86083020
Implicit process is now 86083020
Loading User Symbols
1: kd> !process 86083020
[...]
THREAD 860b0db0 Cid 4560.4e4c Teb: 7ffdd000 Win32Thread: bc1bf4d0 WAIT: (Unknown) KernelMode Non-Alertable
860b0e28 NotificationTimer
1: kd> .thread 860b0db0
Implicit thread is now 860b0db0
1: kd> kv 100
ChildEBP RetAddr Args to Child
ae7ec76c 80833ec5 860b0db0 860b0ea0 00000000 nt!KiSwapContext+0x26
ae7ec798 80829069 0000001e 00000000 bae016a0 nt!KiSwapThread+0x2e5
ae7ec7e0 badff394 00000000 00000000 ffdff5f0 nt!KeDelayExecutionThread+0x2ab
[...]
0012f6ac 7c8024d5 00000000 00000000 00a43280 kernel32!CreateProcessInternalA+0x28b
0012f6e4 00401b31 00000000 00a43280 00000000 kernel32!CreateProcessA+0×2c
[…]
1: kd> da /c 100 00a43280
00a43280 “wscript.exe C:\Scripts\script.vbs parameters”
The examination of that script showed that it contained a coding error resulted in an infinite loop.
- Dmitry Vostokov @ DumpAnalysis.org -