Software Diagnostics Library

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 -

This entry was posted on Tuesday, February 16th, 2010 at 12:39 am and is filed under Crash Dump Analysis, Crash Dump Patterns. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.