Crash Dump Analysis Patterns (Part 42f)
Here we show an example of a wait chain involving process objects. This Wait Chain pattern variation is similar to threads waiting for thread objects. When looking at stack trace collection from a complete memory dump file we see several threads in a set of processes are blocked in ALPC wait chain:
THREAD fffffa80110b8700 Cid 12f8.1328 Teb: 000000007ef9a000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
fffffa80110b8a90 Semaphore Limit 0x1
Waiting for reply to ALPC Message fffff8801c7096e0 : queued at port fffffa8010c9d9a0 : owned by process fffffa80109c8c10
Not impersonating
DeviceMap fffff880097ce5e0
Owning Process fffffa80110ad510 Image: ProcessA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 14004580 Ticks: 62149 (0:00:16:09.530)
Context Switch Count 25100
UserTime 00:00:00.421
KernelTime 00:00:00.218
Win32 Start Address 0×0000000074ca29e1
Stack Init fffffa6003bc4db0 Current fffffa6003bc4670
Base fffffa6003bc5000 Limit fffffa6003bbf000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa60`03bc46b0 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`03bc47f0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`03bc4860 fffff800`01ce4e72 nt!KeWaitForSingleObject+0×2cb
fffffa60`03bc48f0 fffff800`01f32f34 nt!AlpcpSignalAndWait+0×92
fffffa60`03bc4980 fffff800`01f2f9c6 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`03bc49e0 fffff800`01f1f52f nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`03bc4b00 fffff800`01cb7973 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`03bc4bb0 00000000`7713756a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`03bc4c20)
00000000`016ee5b8 00000000`74f9993f ntdll!ZwAlpcSendWaitReceivePort+0xa
00000000`016ee5c0 00000000`74f8a996 wow64!whNtAlpcSendWaitReceivePort+0×5f
00000000`016ee610 00000000`75183688 wow64!Wow64SystemServiceEx+0xca
00000000`016eeec0 00000000`74f8ab46 wow64cpu!ServiceNoTurbo+0×28
00000000`016eef50 00000000`74f8a14c wow64!RunCpuSimulation+0xa
00000000`016eef80 00000000`771605a8 wow64!Wow64LdrpInitialize+0×4b4
00000000`016ef4e0 00000000`771168de ntdll! ?? ::FNODOBFM::`string’+0×20aa1
00000000`016ef590 00000000`00000000 ntdll!LdrInitializeThunk+0xe
1: kd> !alpc /m fffff8801c7096e0
Message @ fffff8801c7096e0
MessageID : 0x263C (9788)
CallbackID : 0x29F2A02 (43985410)
SequenceNumber : 0x000009FE (2558)
Type : LPC_REQUEST
DataLength : 0x0058 (88)
TotalLength : 0x0080 (128)
Canceled : No
Release : No
ReplyWaitReply : No
Continuation : Yes
OwnerPort : fffffa8015128040 [ALPC_CLIENT_COMMUNICATION_PORT]
WaitingThread : fffffa80110b8700
QueueType : ALPC_MSGQUEUE_PENDING
QueuePort : fffffa8010c9d9a0 [ALPC_CONNECTION_PORT]
QueuePortOwnerProcess : fffffa80109c8c10 (ProcessB.exe)
ServerThread : fffffa8013b87bb0
QuotaCharged : No
CancelQueuePort : 0000000000000000
CancelSequencePort : 0000000000000000
CancelSequenceNumber : 0×00000000 (0)
ClientContext : 0000000009b49208
ServerContext : 0000000000000000
PortContext : 000000000280f0d0
CancelPortContext : 0000000000000000
SecurityData : 0000000000000000
View : 0000000000000000
If we look at process fffffa80109c8c10 and its thread fffffa8013b87bb0 we would see that it is blocked as well on some kind of a lock:
THREAD fffffa8013b87bb0 Cid 0358.2c60 Teb: 000007fffff7e000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa8010bca370 Semaphore Limit 0x7fffffff
fffffa8013b87c68 NotificationTimer
Impersonation token: fffff8801e614060 (Level Impersonation)
DeviceMap fffff880097ce5e0
Owning Process fffffa80109c8c10 Image: ProcessB.exe
Attached Process N/A Image: N/A
Wait Start TickCount 14004580 Ticks: 62149 (0:00:16:09.530)
Context Switch Count 134
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address RPCRT4!ThreadStartRoutine (0x000007feff267780)
Stack Init fffffa6035a1fdb0 Current fffffa6035a1f940
Base fffffa6035a20000 Limit fffffa6035a1a000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa60`35a1f980 fffff800`01cba0fa nt!KiSwapContext+0x7f
fffffa60`35a1fac0 fffff800`01caedab nt!KiSwapThread+0x13a
fffffa60`35a1fb30 fffff800`01f1d608 nt!KeWaitForSingleObject+0x2cb
fffffa60`35a1fbc0 fffff800`01cb7973 nt!NtWaitForSingleObject+0x98
fffffa60`35a1fc20 00000000`77136d5a nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60`35a1fc20)
00000000`0486ec28 00000000`770f559f ntdll!ZwWaitForSingleObject+0xa
00000000`0486ec30 00000000`ff77d4e9 ntdll!RtlAcquireResourceShared+0xd1
00000000`0486ec70 00000000`ff77fb4d ProcessB!CLock::CLock+0×61
[…]
00000000`0486eee0 000007fe`ff261f46 RPCRT4!Invoke+0×65
00000000`0486ef40 000007fe`ff26254d RPCRT4!NdrStubCall2+0×348
00000000`0486f520 000007fe`ff2868d4 RPCRT4!NdrServerCall2+0×1d
00000000`0486f550 000007fe`ff2869f0 RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`0486f580 000007fe`ff287402 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×100
00000000`0486f670 000007fe`ff287080 RPCRT4!LRPC_SCALL::DispatchRequest+0×1c2
00000000`0486f6e0 000007fe`ff2862bb RPCRT4!LRPC_SCALL::HandleRequest+0×200
00000000`0486f800 000007fe`ff285e1a RPCRT4!LRPC_ADDRESS::ProcessIO+0×44a
00000000`0486f920 000007fe`ff267769 RPCRT4!LOADABLE_TRANSPORT::ProcessIOEvents+0×24a
00000000`0486f9d0 000007fe`ff267714 RPCRT4!ProcessIOEventsWrapper+0×9
00000000`0486fa00 000007fe`ff2677a4 RPCRT4!BaseCachedThreadRoutine+0×94
00000000`0486fa40 00000000`76fdbe3d RPCRT4!ThreadStartRoutine+0×24
00000000`0486fa70 00000000`77116a51 kernel32!BaseThreadInitThunk+0xd
00000000`0486faa0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d
There are many such threads and inspection of all threads in the process fffffa80109c8c10 reveals another thread waiting for an ALPC reply:
THREAD fffffa8010c9b060 Cid 0358.02ac Teb: 000007fffffd3000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
fffffa8010c9b3f0 Semaphore Limit 0x1
Waiting for reply to ALPC Message fffff88011994cf0 : queued at port fffffa8010840360 : owned by process fffffa801083e120
Not impersonating
DeviceMap fffff880000073d0
Owning Process fffffa80109c8c10 Image: ProcessB.exe
Attached Process N/A Image: N/A
Wait Start TickCount 13986969 Ticks: 79760 (0:00:20:44.263)
Context Switch Count 712
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address ntdll!TppWorkerThread (0×0000000077107cb0)
Stack Init fffffa6004bfbdb0 Current fffffa6004bfb670
Base fffffa6004bfc000 Limit fffffa6004bf6000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffffa60`04bfb6b0 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`04bfb7f0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`04bfb860 fffff800`01ce4e72 nt!KeWaitForSingleObject+0×2cb
fffffa60`04bfb8f0 fffff800`01f32f34 nt!AlpcpSignalAndWait+0×92
fffffa60`04bfb980 fffff800`01f2f9c6 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`04bfb9e0 fffff800`01f1f52f nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`04bfbb00 fffff800`01cb7973 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`04bfbbb0 00000000`7713756a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`04bfbc20)
00000000`00c3f2f8 00000000`771872c9 ntdll!ZwAlpcSendWaitReceivePort+0xa
[…]
00000000`00c3f810 00000000`77107fd0 ntdll!RtlpTpWorkCallback+0xf2
00000000`00c3f8c0 00000000`76fdbe3d ntdll!TppWorkerThread+0×3d6
00000000`00c3fb40 00000000`77116a51 kernel32!BaseThreadInitThunk+0xd
00000000`00c3fb70 00000000`00000000 ntdll!RtlUserThreadStart+0×1d
1: kd> !alpc /m fffff88011994cf0
Message @ fffff88011994cf0
MessageID : 0x033C (828)
CallbackID : 0x29CEF57 (43839319)
SequenceNumber : 0x000000D8 (216)
Type : LPC_REQUEST
DataLength : 0x000C (12)
TotalLength : 0x0034 (52)
Canceled : No
Release : No
ReplyWaitReply : No
Continuation : Yes
OwnerPort : fffffa8010c99040 [ALPC_CLIENT_COMMUNICATION_PORT]
WaitingThread : fffffa8010c9b060
QueueType : ALPC_MSGQUEUE_PENDING
QueuePort : fffffa8010840360 [ALPC_CONNECTION_PORT]
QueuePortOwnerProcess : fffffa801083e120 (ProcessC.exe)
ServerThread : fffffa80109837d0
QuotaCharged : No
CancelQueuePort : 0000000000000000
CancelSequencePort : 0000000000000000
CancelSequenceNumber : 0×00000000 (0)
ClientContext : 0000000000000000
ServerContext : 0000000000000000
PortContext : 00000000005f3400
CancelPortContext : 0000000000000000
SecurityData : 0000000000000000
View : 0000000000000000
We see that ProcessC thread fffffa80109837d0 is waiting for a process object fffffa801434cb40:
THREAD fffffa80109837d0 Cid 027c.02b0 Teb: 000007fffffdb000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa801434cb40 ProcessObject
Not impersonating
DeviceMap fffff880000073d0
Owning Process fffffa801083e120 Image: ProcessC.exe
Attached Process N/A Image: N/A
Wait Start TickCount 13986969 Ticks: 79760 (0:00:20:44.263)
Context Switch Count 520
UserTime 00:00:00.000
KernelTime 00:00:00.062
Win32 Start Address 0×000000004826dcf4
Stack Init fffffa6002547db0 Current fffffa6002547940
Base fffffa6002548000 Limit fffffa6002542000 Call 0
Priority 13 BasePriority 11 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffffa60`02547980 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`02547ac0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`02547b30 fffff800`01f1d608 nt!KeWaitForSingleObject+0×2cb
fffffa60`02547bc0 fffff800`01cb7973 nt!NtWaitForSingleObject+0×98
fffffa60`02547c20 00000000`77136d5a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`02547c20)
00000000`0024f7c8 00000000`4826ea97 ntdll!ZwWaitForSingleObject+0xa
00000000`0024f7d0 00000000`4826ef44 ProcessC!TerminatePID+0xa3
[…]
00000000`0024fc90 00000000`00000000 ntdll!RtlUserThreadStart+0×29
When we inspect process fffffa801434cb40 we see that it has only one thread with many usual threads missing. The blocked thread stack trace has DriverA module code waiting for an event:
1: kd> !process fffffa801434cb40 ff
PROCESS fffffa801434cb40
SessionId: 1 Cid: a0c8 Peb: 7fffffdc000 ParentCid: 1c08
DirBase: 19c6cc000 ObjectTable: fffff8801767ee00 HandleCount: 287.
Image: ProcessD.exe
VadRoot fffffa8021be17d0 Vads 71 Clone 0 Private 955. Modified 1245. Locked 0.
DeviceMap fffff880000073d0
Token fffff880187cb3c0
ElapsedTime 00:49:23.432
UserTime 00:00:00.686
KernelTime 00:00:00.904
QuotaPoolUsage[PagedPool] 208080
QuotaPoolUsage[NonPagedPool] 6720
Working Set Sizes (now,min,max) (2620, 50, 345) (10480KB, 200KB, 1380KB)
PeakWorkingSetSize 3136
VirtualSize 101 Mb
PeakVirtualSize 222 Mb
PageFaultCount 13495
MemoryPriority BACKGROUND
BasePriority 13
CommitCharge 1154
[...]
THREAD fffffa8012249b30 Cid a0c8.31b4 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffffa801180a6a0 SynchronizationEvent
Not impersonating
DeviceMap fffff880000073d0
Owning Process fffffa801434cb40 Image: ProcessD.exe
Attached Process N/A Image: N/A
Wait Start TickCount 13986969 Ticks: 79760 (0:00:20:44.263)
Context Switch Count 97
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address DllA (0xfffff96000eeada0)
Stack Init fffffa601b841db0 Current fffffa601b841960
Base fffffa601b842000 Limit fffffa601b83c000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffffa60`1b8419a0 fffff800`01cba0fa nt!KiSwapContext+0x7f
fffffa60`1b841ae0 fffff800`01caedab nt!KiSwapThread+0x13a
fffffa60`1b841b50 fffff960`00eeb281 nt!KeWaitForSingleObject+0x2cb
fffffa60`1b841c20 fffff800`01ec7bc7 DriverA+0×4b281
fffffa60`1b841d50 fffff800`01cf65a6 nt!PspSystemThreadStartup+0×57
fffffa60`1b841d80 00000000`00000000 nt!KiStartSystemThread+0×16
We therefore recommend to contact the vendor of DriverA component.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
February 27th, 2010 at 2:07 am
[…] Thread 866d63e8 is waiting for a process 86b33b30: […]
September 22nd, 2010 at 10:32 am
[…] Wait Chain (process objects) […]
September 22nd, 2010 at 10:57 am
[…] Experts Magazine Online Today we introduce an icon for Wait Chain (process objects) […]