Archive for June 6th, 2008

Review of Memory Analysis album

Friday, June 6th, 2008

If you remember I promised to review this CD:

 The first Memory Analysis CD album

Finally it arrived by post and here it is:

I’ve just finished listening to it. It is wonderful! Clearly belongs to my Music for Debugging collection. Here is my commentary (italics) on track titles:

1. Chameleon 
   It crashes then hangs then spikes then leaks. You never know what happens next…
2. Silence Before The Storm 
   Waiting for the problem to start dumping memory
3. Appearances 
   Multiple occurrences of the issue ease crash dump collection
4. Memory Analysis 
   Memory dump analysis activity
5. Voices From Heaven 
   It’s my blog full of crash dump analysis patterns
6. Figure In The Fog 
   It’s that DLL! I see it clearly!!!
7. Diamond Tear 
   Customer is happy
8. The Toy Soldier 
9. Tears In Dragon’s Eyes 
   Operating system vendor is happy too
10. Forgotten Song 
   No pasaran (bugs)
11. Skies
   We are debugging gods!

Enjoy :-) 

- Dmitry Vostokov @ -

Crash Dump Analysis Patterns (Part 63)

Friday, June 6th, 2008

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 @ -