Another pattern that we need to pay attention is called Thread Starvation. This happens when some threads or processes have higher priority and favored by OS thread dispatcher effectively starving other threads. If prioritized threads are CPU-bound we also see Spiking Thread pattern. However, if their thread priorities were normal they would have been preempted by other threads and latter threads would not be starved. Here is one example where 2 threads from 2 different applications but from one user session are spiking on 2 processors (threads from other processors have above normal and normal priority):
System Uptime: 0 days 6:40:41.143
0: kd> !running
System Processors f (affinity mask)
Idle Processors None
Prcb Current Next
0 f773a120 89864c86 ................
1 f773d120 89f243d2 ................
2 f7737120 89f61398 ................
3 f773f120 897228a0 ................
0: kd> .thread /r /p 89f61398
Implicit thread is now 89f61398
Implicit process is now 88bcc2e0
Loading User Symbols
0: kd> !thread 89f61398 1f
THREAD 89f61398 Cid 16f8.2058 Teb: 7ffdf000 Win32Thread: bc41aea8 RUNNING on processor 2
Not impersonating
DeviceMap e48a6508
Owning Process 88bcc2e0 Image: application.exe
Wait Start TickCount 1569737 Ticks: 0
Context Switch Count 7201654 LargeStack
UserTime 01:24:06.687
KernelTime 00:14:53.828
Win32 Start Address application (0×0040a52c)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init ba336000 Current ba335d00 Base ba336000 Limit ba330000 Call 0
Priority 24 BasePriority 24 PriorityDecrement 0
ChildEBP RetAddr
0012e09c 762c3b7d USER32!IsWindowVisible
0012e0c4 762d61bb MSVBVM50!RbyCountVisibleDesks+0×3c
0012e0d0 004831f6 MSVBVM50!rtcDoEvents+0×7
0012e348 0046d1ae application+0×831f6
0012e3a0 762ce5a9 application+0×6d1ae
0012e3dc 762ce583 MSVBVM50!CallProcWithArgs+0×20
0012e3f8 762db781 MSVBVM50!InvokeVtblEvent+0×33
0012e434 762cfbc2 MSVBVM50!InvokeEvent+0×32
0012e514 762cfa4a MSVBVM50!EvtErrFireWorker+0×175
0012e55c 762b1aa3 MSVBVM50!EvtErrFire+0×18
0012e5ac 7739bffa MSVBVM50!CThreadPool::GetThreadData+0xf
0012e58c 762cd13b USER32!CallHookWithSEH+0×21
0012e5ac 7739bffa MSVBVM50!VBDefControlProc_2787+0xad
0012e618 762d3348 USER32!CallHookWithSEH+0×21
0012e640 762cda44 MSVBVM50!PushCtlProc+0×2e
0012e668 762cd564 MSVBVM50!CommonGizWndProc+0×4e
0012e6b8 7739b6e3 MSVBVM50!StdCtlWndProc+0×171
0012e6e4 7739b874 USER32!InternalCallWinProc+0×28
0012e75c 7739ba92 USER32!UserCallWinProcCheckWow+0×151
0012e7c4 773a16e5 USER32!DispatchMessageWorker+0×327
0012e7d4 762d616e USER32!DispatchMessageA+0xf
0012e828 762d6054 MSVBVM50!ThunderMsgLoop+0×97
0012e874 762d5f55 MSVBVM50!SCM::FPushMessageLoop+0xaf
0012e8b4 004831f6 MSVBVM50!CMsoComponent::PushMsgLoop+0×24
0012e8c0 00d3b3c8 application+0×831f6
00184110 00000000 0xd3b3c8
0: kd> .thread /r /p 897228a0
Implicit thread is now 897228a0
Implicit process is now 897348a8
Loading User Symbols
0: kd> !thread 897228a0 1f 100
THREAD 897228a0 Cid 2984.2988 Teb: 7ffdf000 Win32Thread: bc381488 RUNNING on processor 3
IRP List:
89794bb8: (0006,0220) Flags: 00000000 Mdl: 8a145878
Not impersonating
DeviceMap e3ec0360
Owning Process 897348a8 Image: application2.exe
Wait Start TickCount 1569737 Ticks: 0
Context Switch Count 10239625 LargeStack
UserTime 02:38:18.890
KernelTime 00:29:36.187
Win32 Start Address application2 (0×00442e4c)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init f1d90000 Current f1d8fd00 Base f1d90000 Limit f1d88000 Call 0
Priority 24 BasePriority 24 PriorityDecrement 0
ChildEBP RetAddr
0012f66c 762d61bb USER32!_SEH_prolog+0×5
0012f678 00fdb0b9 MSVBVM50!rtcDoEvents+0×7
0012f92c 00fca760 application2+0xbdb0b9
0012fa20 762ce5a9 application2+0xbca760
0012fa40 762ce583 MSVBVM50!CallProcWithArgs+0×20
0012fa5c 762db781 MSVBVM50!InvokeVtblEvent+0×33
0012fa98 762cfbc2 MSVBVM50!InvokeEvent+0×32
0012fb78 762cfa4a MSVBVM50!EvtErrFireWorker+0×175
0012fb90 76330b2b MSVBVM50!EvtErrFire+0×18
0012fbf0 762cd13b MSVBVM50!ErrDefMouse_100+0×16d
0012fca4 762cda44 MSVBVM50!VBDefControlProc_2787+0xad
0012fccc 7631c826 MSVBVM50!CommonGizWndProc+0×4e
0012fd08 762cd523 MSVBVM50!StdCtlPreFilter_50+0×9e
0012fd5c 7739b6e3 MSVBVM50!StdCtlWndProc+0×130
0012fd88 7739b874 USER32!InternalCallWinProc+0×28
0012fe00 7739ba92 USER32!UserCallWinProcCheckWow+0×151
0012fe68 773a16e5 USER32!DispatchMessageWorker+0×327
0012fe78 762d616e USER32!DispatchMessageA+0xf
0012fea8 762bb78f MSVBVM50!ThunderMsgLoop+0×97
0012feb8 762d60cb MSVBVM50!MsoFInitPx+0×39
0012fecc 762d6054 MSVBVM50!CMsoCMHandler::FPushMessageLoop+0×1a
0012ff18 762d5f55 MSVBVM50!SCM::FPushMessageLoop+0xaf
0012ffa0 8082ea41 MSVBVM50!CMsoComponent::PushMsgLoop+0×24
0012fef8 762d5f8e nt!KiDeliverApc+0×11f
0012ff18 762d5f55 MSVBVM50!SCM_MsoCompMgr::FPushMessageLoop+0×2f
0012ffa0 8082ea41 MSVBVM50!CMsoComponent::PushMsgLoop+0×24
0012ff18 762d5f55 nt!KiDeliverApc+0×11f
0012ffa0 8082ea41 MSVBVM50!CMsoComponent::PushMsgLoop+0×24
0012ffd4 0012ffc8 nt!KiDeliverApc+0×11f
00000000 00000000 0×12ffc8
What we see here is unusually high Priority and BasePriority values (24 and 24). This means that the base priority for these processes was most likely artificially increased to Realtime. Most processes have base priority 8 (Normal):
0: kd> !thread 88780db0 1f
THREAD 88780db0 Cid 44a8.1b8c Teb: 7ffaf000 Win32Thread: bc315d20 WAIT: (Unknown) UserMode Non-Alertable
887b8650 Semaphore Limit 0x7fffffff
88780e28 NotificationTimer
Not impersonating
DeviceMap e1085298
Owning Process 889263a0 Image: explorer.exe
Wait Start TickCount 1565543 Ticks: 4194 (0:00:01:05.531)
Context Switch Count 7 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.000
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b6754000 Current b6753c0c Base b6754000 Limit b6750000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
b6753c24 80833e8d nt!KiSwapContext+0×26
b6753c50 80829b74 nt!KiSwapThread+0×2e5
b6753c98 809249cd nt!KeWaitForSingleObject+0×346
b6753d48 8088ac4c nt!NtReplyWaitReceivePortEx+0×521
b6753d48 7c8285ec nt!KiFastCallEntry+0xfc
01a2fe18 7c82783b ntdll!KiFastSystemCallRet
01a2fe1c 77c885ac ntdll!NtReplyWaitReceivePortEx+0xc
01a2ff84 77c88792 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×198
01a2ff8c 77c8872d RPCRT4!RecvLotsaCallsWrapper+0xd
01a2ffac 77c7b110 RPCRT4!BaseCachedThreadRoutine+0×9d
01a2ffb8 77e64829 RPCRT4!ThreadStartRoutine+0×1b
01a2ffec 00000000 kernel32!BaseThreadStart+0×34
Some important system processes like csrss.exe have base priority 13 (High) but their threads wait most of the time and this doesn’t create any problems:
0: kd> !thread 887eb3d0 1f
THREAD 887eb3d0 Cid 4cf4.2bd4 Teb: 7ffaf000 Win32Thread: bc141cc0 WAIT: (Unknown) UserMode Non-Alertable
888769b0 SynchronizationEvent
Not impersonating
DeviceMap e1000930
Owning Process 8883f7c0 Image: csrss.exe
Wait Start TickCount 1540456 Ticks: 29281 (0:00:07:37.515)
Context Switch Count 40 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.000
Start Address winsrv!ConsoleInputThread (0×75a81b18)
Stack Init b5c5a000 Current b5c59bac Base b5c5a000 Limit b5c55000 Call 0
Priority 15 BasePriority 13 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
b5c59bc4 80833e8d nt!KiSwapContext+0×26
b5c59bf0 80829b74 nt!KiSwapThread+0×2e5
b5c59c38 bf89b1c3 nt!KeWaitForSingleObject+0×346
b5c59c94 bf89b986 win32k!xxxSleepThread+0×1be
b5c59cec bf89da22 win32k!xxxRealInternalGetMessage+0×46a
b5c59d4c 8088ac4c win32k!NtUserGetMessage+0×3f
b5c59d4c 7c8285ec nt!KiFastCallEntry+0xfc
00ffff64 7739c811 ntdll!KiFastSystemCallRet
00ffff84 75a81c47 USER32!NtUserGetMessage+0xc
00fffff4 00000000 winsrv!ConsoleInputThread+0×16c
However it is very unusual for a process to have Realtime base priority. I can speculate what had really happened before the system crash was forced. The system administrator noticed two applications consuming CPU over the long period of time and decided to intervene. Unfortunately his hand slipped when he was browsing Task Manager Set Priority menu and Realtime was selected instead of Low. Human error…
See also the similar starvation pattern resulted from threads with normal priority.
- Dmitry Vostokov @ DumpAnalysis.org -
