Blocked GUI thread, wait chain and virtualized process: pattern cooperation

CARE: Crash Analysis Report Environment

DATA (Dump Analysis + Trace Analysis) Facebook group
Please join the community of memory (dump) and trace analysis engineers. This group promotes scientific methods and memory dump-based worldview.

Twitter @ DumpAnalysis
You can now follow portal and blog news at DumpAnalysis on Twitter

LinkedIn Group Dr. Watson Enthusiasts
All about Dr. Watson errors and more. Get news, excerpts and progress reports about the forthcoming book The Science of Dr. Watson: An Illustrated History of Debugging (ISBN 978-1906717070)

2010 (0x7DA) - The Year of Dump Analysis
2011 (0x7DB) - 2020 (0x7E4) The Debugging Decade

In one system even Task Manager was hanging and forced complete memory dump reveals a blocked GUI dialog thread waiting for an LPC reply:

THREAD fffffade69e36310  Cid 4b30.4f34  Teb: 000007fffffde000 Win32Thread: fffff97ff3f97620 WAIT: (Unknown) UserMode Non-Alertable
    fffffade69e36678  Semaphore Limit 0x1
Waiting for reply to LPC MessageId a7531ec4:
Current LPC port fffffa8007118190
Not impersonating
DeviceMap                 fffffa80021c6240
Owning Process            fffffadee0332040       Image:         taskmgr.exe
Wait Start TickCount      80209499       Ticks: 5596 (0:00:01:27.437)
Context Switch Count      173                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.031
Win32 Start Address taskmgr!wWinMainCRTStartup (0×000000010001bfe0)
Start Address kernel32!BaseProcessStart (0×0000000077d59620)
Stack Init fffffad7c6e5ae00 Current fffffad7c6e5a8e0
Base fffffad7c6e5b000 Limit fffffad7c6e52000 Call 0
Priority 14 BasePriority 13 PriorityDecrement 0
Child-SP          RetAddr           Call Site
fffffad7`c6e5a920 fffff800`01027752 nt!KiSwapContext+0×85
fffffad7`c6e5aaa0 fffff800`0102835e nt!KiSwapThread+0×3c9
fffffad7`c6e5ab00 fffff800`01283ebb nt!KeWaitForSingleObject+0×5a6
fffffad7`c6e5ab80 fffff800`0102e3fd nt!NtRequestWaitReplyPort+0xa60
fffffad7`c6e5ac70 00000000`77ef0c0a nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad7`c6e5ac70)
00000000`000adef8 000007ff`7fd6df46 ntdll!ZwRequestWaitReplyPort+0xa
00000000`000adf00 000007ff`7fd6e17f RPCRT4!LRPC_CCALL::SendReceive+0×447
00000000`000adfe0 000007ff`7fe974c8 RPCRT4!NdrSendReceive+0xf6
00000000`000ae010 000007ff`7fe975bd RPCRT4!NdrpClientCall2+0×7e2
00000000`000ae5f0 000007ff`7d4d8a0d RPCRT4!NdrClientCall2+0×1d
00000000`000ae620 00000001`00011029 WINSTA!WinStationGetProcessSid+0xfd
00000000`000ae6a0 00000001`00010e3b taskmgr!CProcInfo::SetProcessUsername+0×189
00000000`000ae930 00000001`000118e9 taskmgr!CProcInfo::SetData+0×53b
00000000`000aebb0 00000001`000122f4 taskmgr!CProcPage::UpdateProcInfoArray+0×449
00000000`000aee70 00000001`00013eab taskmgr!CProcPage::TimerEvent+0×14
00000000`000aeea0 00000001`00004e8f taskmgr!CProcPage::Initialize+0×29b
00000000`000af320 00000001`000070e8 taskmgr!MainWnd_OnInitDialog+0×2ff
00000000`000af620 00000000`77c34582 taskmgr!MainWindowProc+0×3f8
00000000`000af680 00000000`77c34bf2 USER32!UserCallDlgProcCheckWow+0×210
00000000`000af760 00000000`77c2ff5f USER32!DefDlgProcWorker+0xf6
00000000`000af7f0 00000000`77c29beb USER32!InternalCreateDialog+0×16a7
00000000`000af980 00000001`00007c97 USER32!CreateDialogParamW+0xab
00000000`000afa00 00000001`0001c24b taskmgr!wWinMain+0×5f7
00000000`000afed0 00000000`77d5964c taskmgr!wWinMainCRTStartup+0×26b
00000000`000aff80 00000000`00000000 kernel32!BaseProcessStart+0×29

We search for that LPC message:

6: kd> !lpc message a7531ec4
Searching message a7531ec4 in threads ...
    Server thread fffffade6b8cf7a0 is working on message a7531ec4
Client thread fffffade69e36310 waiting a reply from a7531ec4                         
[…]

and then examine the corresponding server thread (for visual clarity only 1 argument is shown for each function call):

6: kd> !thread fffffade6b8cf7a0 16
THREAD fffffade6b8cf7a0  Cid 0238.8ff4  Teb: 000007fffff48000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffade6f2e93c0  SynchronizationEvent
Impersonation token:  fffffa8013a17700 (Level Impersonation)
DeviceMap                 fffffa80021c6240
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      80209499       Ticks: 5596 (0:00:01:27.437)
Context Switch Count      40138            
UserTime                  00:00:00.140
KernelTime                00:00:00.312
Win32 Start Address 0×00000000a7531ec4
LPC Server thread working on message Id a7531ec4
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad867f5ae00 Current fffffad867f5a950
Base fffffad867f5b000 Limit fffffad867f55000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Child-SP          RetAddr           : Args to Child     : Call Site
fffffad8`67f5a990 fffff800`01027752 : fffffa80`071181f0 : nt!KiSwapContext+0×85
fffffad8`67f5ab10 fffff800`0102835e : 00000000`00000000 : nt!KiSwapThread+0×3c9
fffffad8`67f5ab70 fffff800`0127f03f : 00000000`00000000 : nt!KeWaitForSingleObject+0×5a6
fffffad8`67f5abf0 fffff800`0102e3fd : fffffade`6b8cf7a0 : nt!NtWaitForSingleObject+0xc1
fffffad8`67f5ac70 00000000`77ef0a2a : 00000000`77efb9a6 : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`67f5ac70)
00000000`04d0f098 00000000`77efb9a6 : 00000000`00000000 : ntdll!NtWaitForSingleObject+0xa
00000000`04d0f0a0 00000000`77efba10 : 000007ff`7b8c3500 : ntdll!RtlpWaitOnCriticalSection+0×240
00000000`04d0f120 000007ff`7b887042 : 00000000`04d0f300 : ntdll!RtlEnterCriticalSection+0xa9
[…]
00000000`04d0f190 000007ff`7fe96cc9 : 00000000`00000048 : RPCRT4!Invoke+0×65
00000000`04d0f210 000007ff`7fe9758d : 00000000`04d0f8f0 : RPCRT4!NdrStubCall2+0×54d
00000000`04d0f7d0 000007ff`7fd697b4 : 00000000`0450a8fd : RPCRT4!NdrServerCall2+0×1d
00000000`04d0f800 000007ff`7fd6990d : 00000000`00377aa0 : RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`04d0f830 000007ff`7fd69766 : 00000000`00000001 : RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×50d
00000000`04d0f9a0 000007ff`7fd6b214 : 00000000`06c18ba0 : RPCRT4!RPC_INTERFACE::DispatchToStub+0×2ec
00000000`04d0fa20 000007ff`7fd6b9e3 : 00000000`06c18ba0 : RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×63b
00000000`04d0fae0 000007ff`7fd7007c : 00000000`048348a0 : RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×3bf
00000000`04d0fba0 000007ff`7fd45369 : 00000000`0525fd30 : RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×710
00000000`04d0feb0 000007ff`7fd65996 : 00000000`00000000 : RPCRT4!RecvLotsaCallsWrapper+0×9
00000000`04d0fee0 000007ff`7fd65d51 : 00000000`0492de90 : RPCRT4!BaseCachedThreadRoutine+0xde
00000000`04d0ff50 00000000`77d6b6da : 00000000`77d6b6a0 : RPCRT4!ThreadStartRoutine+0×21
00000000`04d0ff80 00000000`00000000 : 00000000`00000000 : kernel32!BaseThreadStart+0×3a 

We see the thread above is waiting for a critical section and we examine it using !cs WinDbg extension command after switching to the process context of that thread:

6: kd> .process /r /p fffffade6f337040
Implicit process is now fffffade`6f337040
Loading User Symbols

6: kd> !cs 000007ff`7b8c3500
Critical section   = 0×000007ff7b8c3500 (DllA!Lock+0×0)
DebugInfo          = 0×00000000000ffea0
LOCKED
LockCount          = 0×8
WaiterWoken        = No
OwningThread       = 0×0000000000004100
RecursionCount     = 0×1
LockSemaphore      = 0×8E0
SpinCount          = 0×0000000000000000 

From the output we know the critical section owner thread and examine it too (function call arguments are not shown for visual clarity):

6: kd> !thread -t 4100 16
Looking for thread Cid = 4100 …
THREAD fffffade6b9df4f0  Cid 0238.4100  Teb: 000007fffff58000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffadff5edadc0  Mutant - owning thread fffffadfe2486bf0
Impersonation token:  fffffa8010197250 (Level Impersonation)
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      79672315       Ticks: 542780 (0:02:21:20.937)
Context Switch Count      174            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×00000000a75007ac
LPC Server thread working on message Id a75007ac
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad83a94ee00 Current fffffad83a94e950
Base fffffad83a94f000 Limit fffffad83a949000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad8`3a94e990 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad8`3a94eb10 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad8`3a94eb70 fffff800`0127f03f : nt!KeWaitForSingleObject+0×5a6
fffffad8`3a94ebf0 fffff800`0102e3fd : nt!NtWaitForSingleObject+0xc1
fffffad8`3a94ec70 00000000`77ef0a2a : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`3a94ec70)
00000000`03c8efa8 000007ff`7b880427 : ntdll!NtWaitForSingleObject+0xa
[…]
00000000`03c8f1a0 000007ff`7fe96cc9 : RPCRT4!Invoke+0×65
00000000`03c8f210 000007ff`7fe9758d : RPCRT4!NdrStubCall2+0×54d
00000000`03c8f7d0 000007ff`7fd697b4 : RPCRT4!NdrServerCall2+0×1d
00000000`03c8f800 000007ff`7fd6990d : RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`03c8f830 000007ff`7fd69766 : RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×50d
00000000`03c8f9a0 000007ff`7fd6b214 : RPCRT4!RPC_INTERFACE::DispatchToStub+0×2ec
00000000`03c8fa20 000007ff`7fd6b9e3 : RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×63b
00000000`03c8fae0 000007ff`7fd7007c : RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×3bf
00000000`03c8fba0 000007ff`7fd45369 : RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×710
00000000`03c8feb0 000007ff`7fd65996 : RPCRT4!RecvLotsaCallsWrapper+0×9
00000000`03c8fee0 000007ff`7fd65d51 : RPCRT4!BaseCachedThreadRoutine+0xde
00000000`03c8ff50 00000000`77d6b6da : RPCRT4!ThreadStartRoutine+0×21
00000000`03c8ff80 00000000`00000000 : kernel32!BaseThreadStart+0×3a

We see that it is waiting for a mutant and examine its owner thread:

6: kd> !thread fffffadfe2486bf0 16
THREAD fffffadfe2486bf0  Cid 0238.7010  Teb: 000007fffff5e000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffadfe2486f58  Semaphore Limit 0x1
Waiting for reply to LPC MessageId a7507485:
Current LPC port fffffa8006822c80
Not impersonating
DeviceMap                 fffffa8000003790
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      79744596       Ticks: 470499 (0:02:02:31.546)
Context Switch Count      29636            
UserTime                  00:00:00.062
KernelTime                00:00:00.156
Win32 Start Address 0×00000000a74ff6e4
LPC Server thread working on message Id a74ff6e4
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad7d98a0e00 Current fffffad7d98a08e0
Base fffffad7d98a1000 Limit fffffad7d989b000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad7`d98a0920 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad7`d98a0aa0 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad7`d98a0b00 fffff800`01283ebb : nt!KeWaitForSingleObject+0×5a6
fffffad7`d98a0b80 fffff800`0102e3fd : nt!NtRequestWaitReplyPort+0xa60
fffffad7`d98a0c70 00000000`77ef0c0a : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad7`d98a0c70)
00000000`0430dc18 000007ff`7fd6df46 : ntdll!ZwRequestWaitReplyPort+0xa
00000000`0430dc20 000007ff`7fd6e17f : RPCRT4!LRPC_CCALL::SendReceive+0×447
00000000`0430dd10 000007ff`7fe974c8 : RPCRT4!NdrSendReceive+0xf6
00000000`0430dd40 000007ff`7fe975bd : RPCRT4!NdrpClientCall2+0×7e2
00000000`0430e320 00000000`676b1dd7 : RPCRT4!NdrClientCall2+0×1d
[…]

The thread above is waiting for an LPC message and we examine its corresponding server thread:

6: kd> !lpc message a7507485
Searching message a7507485 in threads ...
Client thread fffffadfe2486bf0 waiting a reply from a7507485                         
    Server thread fffffade6f3c9720 is working on message a7507485                        
[...]

6: kd> !thread fffffade6f3c9720 16
THREAD fffffade6f3c9720  Cid 6308.a1c8  Teb: 000000007ef24000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffade68d31a40  SynchronizationEvent
Not impersonating
DeviceMap                 fffffa80016ce1b0
Owning Process            fffffade69c29430       Image:         AppA.exe
Wait Start TickCount      79744596       Ticks: 470499 (0:02:02:31.546)
Context Switch Count      7230            
UserTime                  00:00:00.218
KernelTime                00:00:00.109
Win32 Start Address 0×00000000a7507485
LPC Server thread working on message Id a7507485
Start Address kernel32!BaseThreadStartThunk (0×000000007d4d1504)
Stack Init fffffad83f7e4e00 Current fffffad83f7e4950
Base fffffad83f7e5000 Limit fffffad83f7df000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad8`3f7e4990 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad8`3f7e4b10 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad8`3f7e4b70 fffff800`0127f03f : nt!KeWaitForSingleObject+0×5a6
fffffad8`3f7e4bf0 fffff800`0102e3fd : nt!NtWaitForSingleObject+0xc1
fffffad8`3f7e4c70 00000000`78b842d9 : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`3f7e4c70)
00000000`0257f108 00000000`78b840e5 : wow64cpu!CpupSyscallStub+0×9
00000000`0257f110 00000000`6b006a5a : wow64cpu!Thunk0ArgReloadState+0×1a
00000000`0257f180 00000000`6b005e0d : wow64!RunCpuSimulation+0xa
00000000`0257f1b0 00000000`77f109f0 : wow64!Wow64LdrpInitialize+0×2ed

00000000`0257f6f0 00000000`77ef30a5 : ntdll!LdrpInitialize+0×2aa
00000000`0257f7d0 00000000`7d4d1504 : ntdll!KiUserApcDispatcher+0×15 (TrapFrame @ 00000000`0257fb38)
00000000`0257fcc8 00000000`00000000 : kernel32!BaseThreadStartThunk

We see the thread belongs to a virtualized WOW64 process and presently I’m not aware of how to get its 32-bit stacks from complete memory dumps. WOW64 extensions seems only working in process user dumps. Therefore I recommended to get a userdump of AppA process using 32-bit version of userdump.exe as soon as the same condition starts surfacing again.

- Dmitry Vostokov @ DumpAnalysis.org -

           

Announcements

Coming Soon:

Debugging Notebook: Essential Concepts, WinDbg Commands and Tools

Crash Dump Analysis for System Administrators and Support Engineers

New Magazines:

Debugged! MZ/PE: MagaZine for/from Practicing Engineers


New Books:

Memory Dump Analysis Anthology, Volume 3

First Fault Software Problem Solving: A Guide for Engineers, Managers and Users

x64 Windows Debugging: Practical Foundations

Also available:

Windows Debugging: Practical Foundations

DLL List Landscape: The Art from Computer Memory Space

Dumps, Bugs and Debugging Forensics: The Adventures of Dr. Debugalov

WinDbg: A Reference Poster and Learning Cards

Memory Dump Analysis Anthology, Volume 2

Memory Dump Analysis Anthology, Volume 1

New Children's Book:

Baby Turing

3 Responses to “Blocked GUI thread, wait chain and virtualized process: pattern cooperation”

  1. Yuhong Bao Says:

    “We see the thread belongs to a virtualized WOW64 process and presently I’m not aware of how to get its 32-bit stacks from complete memory dumps”
    Try .thread /w.

  2. Dmitry Vostokov Says:

    Thanks! I’ve tried and it works. I’m going to write a blog post now about my experiences

  3. Dmitry Vostokov Says:

    Here we go:

    http://www.dumpanalysis.org/blog/index.php/2009/02/06/32-bit-stack-traces-from-x64-complete-dumps/

    Thanks again!

Leave a Reply