Hello my name is Roy; I’m an EE on the Microsoft global escalation services / CPR team. This blog post continues my previous posts on LPC.
Below I will discuss scenarios that are simulated to depict actual issues encountered by Microsoft Customer Support Services. The two following scenarios deal with client threads waiting for LPC reply and hence in some way leading to user experience of a hung system or component.
CASE1 – When everything in LPC looks intact
In this scenario tracing the reason for client threads wait is possible through LPC data structures and extensions.
The issue is a hung SMS (Systems Management Server) service. The OS (operating system) itself is working fine. It is just SMS that has hung.
Taking a user mode hang dump (adplus.vbs hang mode dump) does not help since all we see is that threads in SMS are making RPC calls and are stuck. We need to investigate where these RPC calls are stuck. From the user dump we can see one important thing about the RPC calls is that they are implemented over LPC. LPC is completely implemented in the kernel and hence taking a kernel dump would be the next step in this case.
02e9e698 7c821c94 ntdll!KiFastSystemCallRet
02e9e69c 77c72700 ntdll!NtRequestWaitReplyPort+0xc <--- RPC implemented over LPC
02e9e6f4 77c713ba RPCRT4!LRPC_CCALL::SendReceive+0x230
02e9e700 77788056 RPCRT4!I_RpcSendReceive+0x24 <--- RPC calls made
02e9e71c 77788011 ole32!ThreadSendReceive+0xf5
02e9e738 77787ed7 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x112
02e9e818 77695349 ole32!CRpcChannelBuffer::SendReceive2+0xc1
02e9e884 776952e1 ole32!CAptRpcChnl::SendReceive+0xab
02e9e8d8 77ce127e ole32!CCtxComChnl::SendReceive+0x113
02e9e8f4 77ce13ca RPCRT4!NdrProxySendReceive+0x43
02e9ecdc 77ce11bd RPCRT4!NdrClientCall2+0x206
02e9ecfc 77c53a12 RPCRT4!ObjectStublessClient+0x8b
02e9ed0c 77688fd2 RPCRT4!ObjectStubless+0xf
02e9ed70 7768915a ole32!CRpcResolver::CreateInstance+0x14e
02e9efbc 776a9b68 ole32!CClientContextActivator::CreateInstance+0xfa
02e9effc 776a9a9a ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
02e9f7b0 776b1275 ole32!ICoCreateInstanceEx+0x3cc
02e9f7d8 776b1244 ole32!CComActivator::DoCreateInstance+0x28
02e9f7fc 74cf1a51 ole32!CoCreateInstanceEx+0x23
02e9f830 74cf19fe wbemprox!CDCOMTrans::DoActualCCI+0x3d
02e9f874 74cf16b1 wbemprox!CDCOMTrans::DoCCI+0x12d
02e9f934 74cf152e wbemprox!CDCOMTrans::DoActualConnection+0x25f
02e9f960 74cf22ab wbemprox!CDCOMTrans::DoConnection+0x25
02e9f9a0 1806eaa9 wbemprox!CLocator::ConnectServer+0x7c
WARNING: Stack unwind information not available. Following frames may be wrong.
02e9fa50 186c31b6 ccmcore!CCM::Utility::Wmi::Namespace::Open+0x1a2
02e9fb44 186c357f PolicyAgent!DllUnregisterServer+0x10d8
02e9fbb0 18706a63 PolicyAgent!DllUnregisterServer+0x14a1
02e9fc8c 18708899 PolicyAgentEndpoint!DllGetClassObject+0x73d2
02e9fd6c 187097d9 PolicyAgentEndpoint!DllGetClassObject+0x9208
02e9fde0 01068bb8 PolicyAgentEndpoint!DllGetClassObject+0xa148
02e9fe6c 7c83b332 CcmExec+0x68bb8
02e9fec8 7c8161d0 ntdll!RtlpWaitOrTimerCallout+0x74
02e9feec 7c81a3c5 ntdll!RtlpAsyncWaitCallbackCompletion+0x37
02e9ff44 7c8200fc ntdll!RtlpWorkerCallout+0x71
02e9ff64 7c81a3fa ntdll!RtlpExecuteWorkerRequest+0x4f
02e9ff78 7c82017f ntdll!RtlpApcCallout+0x11
02e9ffb8 77e6608b ntdll!RtlpWorkerThread+0x61
02e9ffec 00000000 kernel32!BaseThreadStart+0x34
We examine threads belonging to ccmexec.exe from the kernel dump.
0: kd> !process 0 0 ccmexec.exe
PROCESS 895a6430 SessionId: 0 Cid: 01c8 Peb: 7ffde000 ParentCid: 0278
DirBase: 6f3c7000 ObjectTable: e22d6b00 HandleCount: 832.
Image: CcmExec.exe
0: kd> .process /p /r 895a6430
Implicit process is now 895a6430
Loading User Symbols
............................................................................................
0: kd> !thread 88e75b10
THREAD 88e75b10 Cid 01c8.0de0 Teb: 7ffa6000 Win32Thread: e2365ea8 WAIT: (WrLpcReply) UserMode Non-Alertable
88e75cfc Semaphore Limit 0x1
Waiting for reply to LPC MessageId 00039236:
Current LPC port e2327022
Not impersonating
DeviceMap e10018a8
Owning Process 895a6430 Image: CcmExec.exe
Wait Start TickCount 99831 Ticks: 46825 (0:00:12:11.640)
Context Switch Count 14119 LargeStack
UserTime 00:00:00.125
KernelTime 00:00:00.046
Win32 Start Address ntdll!RtlpWorkerThread (0x7c83ad38)
Start Address kernel32!BaseThreadStartThunk (0x77e6b5f3)
Stack Init b9425000 Current b9424c08 Base b9425000 Limit b9421000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr Args to Child
b9424c20 8083e6a2 88e75b88 88e75b10 88e75bb8 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b9424c4c 8083f164 88e75cfc 88e75cd0 88e75b10 nt!KiSwapThread+0x284 (FPO: [Non-Fpo])
b9424c94 8093983f 88e75cfc 00000011 b9424d01 nt!KeWaitForSingleObject+0x346 (FPO: [Non-Fpo])
b9424d50 80834d3f 00000114 0017db40 0017db40 nt!NtRequestWaitReplyPort+0x776 (FPO: [Non-Fpo])
b9424d50 7c82ed54 00000114 0017db40 0017db40 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b9424d64)
02e9e698 7c821c94 77c72700 00000114 0017db40 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
02e9e69c 77c72700 00000114 0017db40 0017db40 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])
02e9e6f4 77c713ba 00127fd4 02e9e71c 77788056 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [Non-Fpo])
02e9e700 77788056 00127fd4 02e9e800 0009f488 RPCRT4!I_RpcSendReceive+0x24 (FPO: [Non-Fpo])
02e9e71c 77788011 00000000 00000000 00000000 ole32!ThreadSendReceive+0xf5 (FPO: [Non-Fpo])
02e9e738 77787ed7 02e9e800 02e9e900 0009f488 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x112 (FPO: [Non-Fpo])
02e9e818 77695349 0009f488 02e9e910 02e9e900 ole32!CRpcChannelBuffer::SendReceive2+0xc1 (FPO: [Non-Fpo])
02e9e884 776952e1 0009f488 02e9e910 02e9e900 ole32!CAptRpcChnl::SendReceive+0xab (FPO: [Non-Fpo])
02e9e8d8 77ce127e 0009f488 02e9e910 02e9e900 ole32!CCtxComChnl::SendReceive+0x113 (FPO: [Non-Fpo])
02e9e8f4 77ce13ca 000a1934 02e9e93c 0600016e RPCRT4!NdrProxySendReceive+0x43 (FPO: [Non-Fpo])
02e9ecdc 77ce11bd 77676298 7767951e 02e9ed14 RPCRT4!NdrClientCall2+0x206 (FPO: [Non-Fpo])
02e9ecfc 77c53a12 00000014 00000004 02e9ed70 RPCRT4!ObjectStublessClient+0x8b (FPO: [Non-Fpo])
02e9ed0c 77688fd2 000a1934 00000000 02e9f1b4 RPCRT4!ObjectStubless+0xf
02e9ed70 7768915a 02e9f1b4 02e9f704 00000010 ole32!CRpcResolver::CreateInstance+0x14e (FPO: [Non-Fpo])
02e9efbc 776a9b68 7778fcd0 00000000 00000000 ole32!CClientContextActivator::CreateInstance+0xfa (FPO: [Non-Fpo])
02e9effc 776a9a9a 02e9f1b4 00000000 02e9f704 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7 (FPO: [Non-Fpo])
02e9f7b0 776b1275 74cf1a8c 00000000 00000014 ole32!ICoCreateInstanceEx+0x3cc (FPO: [Non-Fpo])
02e9f7d8 776b1244 74cf1a8c 00000000 00000014 ole32!CComActivator::DoCreateInstance+0x28 (FPO: [Non-Fpo])
02e9f7fc 74cf1a51 74cf1a8c 00000000 00000014 ole32!CoCreateInstanceEx+0x23 (FPO: [Non-Fpo])
02e9f830 74cf19fe 02e9f898 00000001 00000000 wbemprox!CDCOMTrans::DoActualCCI+0x3d (FPO: [Non-Fpo])
02e9f874 74cf16b1 02e9f898 00000001 00000000 wbemprox!CDCOMTrans::DoCCI+0x12d (FPO: [Non-Fpo])
02e9f934 74cf152e 01801974 00000000 00000000 wbemprox!CDCOMTrans::DoActualConnection+0x25f (FPO: [Non-Fpo])
02e9f960 74cf22ab 01801974 00000000 00000000 wbemprox!CDCOMTrans::DoConnection+0x25 (FPO: [Non-Fpo])
02e9f9a0 1806eaa9 00b594d0 01801974 00000000 wbemprox!CLocator::ConnectServer+0x7c (FPO: [Non-Fpo])
02e9fa50 186c31b6 0062bdaa 00000001 00000000 ccmcore!CCM::Utility::Wmi::Namespace::Open+0x1a2
02e9fb44 186c357f 02e9fb68 00000001 00000000 PolicyAgent!DllUnregisterServer+0x10d8
02e9fbb0 18706a63 0056a6f0 00000001 00000000 PolicyAgent!DllUnregisterServer+0x14a1
02e9fc8c 18708899 0063cd50 02e9fd0c 02e9fcec PolicyAgentEndpoint!DllGetClassObject+0x73d2
02e9fd6c 187097d9 ffffffff 00000864 00000000 PolicyAgentEndpoint!DllGetClassObject+0x9208
02e9fde0 01068bb8 00566a28 006af398 00000000 PolicyAgentEndpoint!DllGetClassObject+0xa148
02e9fe6c 7c83b332 000008b6 0011c700 0011c7f0 CcmExec+0x68bb8
02e9fec8 7c8161d0 01068a29 000008b6 0011c700 ntdll!RtlpWaitOrTimerCallout+0x74 (FPO: [Non-Fpo])
02e9feec 7c81a3c5 0011c7f0 7c889880 01e89b18 ntdll!RtlpAsyncWaitCallbackCompletion+0x37 (FPO: [Non-Fpo])
02e9ff44 7c8200fc 7c816199 0011c7f0 00000000 ntdll!RtlpWorkerCallout+0x71 (FPO: [Non-Fpo])
02e9ff64 7c81a3fa 00000000 0011c7f0 01e89b18 ntdll!RtlpExecuteWorkerRequest+0x4f (FPO: [Non-Fpo])
The !thread output contains some important information.
The next step is to find the server thread that is processing this LPC message. We will use LPC debugger extensions to trace the server thread.
0: kd> !lpc message 00039236
Searching message 39236 in threads ...
Server thread 89531020 is working on message 39236
Client thread 88e75b10 waiting a reply from 39236
Searching thread 88e75b10 in port rundown queues ...
Server communication port 0xe2300a38
Handles: 1 References: 1
The LpcDataInfoChainHead queue is empty
Connected port: 0xe2327020 Server connection port: 0xe13734b0
Client communication port 0xe2327020
Handles: 1 References: 9
Server connection port e13734b0 Name: epmapper
Handles: 1 References: 93
Server process : 896e1450 (svchost1.exe)
Queue semaphore : 8995ac10
Semaphore state 0 (0x0)
The message queue is empty
Messages in LpcDataInfoChainHead:
0000 e2365188 - Busy Id=0003832f From: 04a8.13f4 Context=80050003 [e1373530 . e297ab00]
Length=0044002c Type=00380001 (LPC_REQUEST)
Data: 00000001 00050242 421e5fa2 9b3b48b4 a695daf5 00000001
0000 e297ab00 - Busy Id=00039232 From: 01c8.14e4 Context=8021000d [e2365188 . e12cbea0]
Data: 00010001 00040242 b8d06b40 b8d06b00 000003f4 000010a0
0000 e12cbea0 - Busy Id=00039236 From: 01c8.0de0 Context=8021000d [e297ab00 . e1297430]
Data: 00010001 00040242 4195c844 8ff87eb3 2b70d0f6 001e001c
0000 e1297430 - Busy Id=0003c96d From: 0204.0224 Context=8022000e [e12cbea0 . e1534a48]
Data: 00010001 00040242 b8bb1b40 b8bb1b00 000003f4 00000fbc
0000 e1534a48 - Busy Id=0003db3b From: 01c8.10e0 Context=8021000d [e1297430 . e2515ca0]
Data: 00010001 00040242 0000dc04 000001c8 7b6ee790 9e8a0590
0000 e2515ca0 - Busy Id=0003db3f From: 01c8.0f5c Context=8021000d [e1534a48 . e29279e8]
0000 e29279e8 - Busy Id=0003db5a From: 01c8.1618 Context=8021000d [e2515ca0 . e1061008]
Data: 00010001 00040242 00000000 00000000 00000000 00000000
0000 e1061008 - Busy Id=0004617f From: 01c8.1220 Context=8021000d [e29279e8 . e295fa80]
Data: 00010001 00040242 00010c20 000001c8 37bd6287 35ebbd53
0000 e295fa80 - Busy Id=0004a38a From: 01c8.1708 Context=8021000d [e1061008 . e2966ea0]
Data: 00010001 00040242 0001a41a 000001c8 cb786dae 60cdf739
0000 e2966ea0 - Busy Id=0004d0c2 From: 04a8.04d4 Context=80050003 [e295fa80 . e1261008]
Data: 00020001 00030242 5415989d 3d8048c1 00070005 00000000
0000 e1261008 - Busy Id=000544d7 From: 01c8.0758 Context=8021000d [e2966ea0 . e1373530]
The LpcDataInfoChainHead queue contains 11 messages
Threads in RunDown queue : 0xe2364fc8 0xe297a940 0xe12cbce0 0xe1297270 0xe1534888 0xe2515ae0 0xe2927828 0xe1060e48 0xe295f8c0 0xe2966ce0 0xe1260e48
Done.
When a client thread sends a message to a server the message ID is stored in the clients ETHREAD.LpcReplyMessageId field. !lpc message searches the message ID in all threads in the system. Once client thread is identified ETHREAD.LpcWaitingOnPort will give the client communication port used for the LPC transaction. This has references to the server communication port and connection port.
!lpc message dumps the message queue for all the port objects. Important thing to note here is that even though the message queue is empty for connection port there are 11 messages chained to LpcDataInfoChainHead. This tells us that 11 messages were dequeued from the server message queue but the server has not replied to any of the messages since once the server responds to a message it is unchained from the LpcDataInfoChainHead list and freed.
Figure [4] LPC Message Queuing stages
The above figure shows messages are first queued to the MsgQueue and then chained to LpcDataInfoChainHead. This kind of chaining only happens when the message contains extra data. This does not happen for a LPC_CONNECTION_REQUEST or if the message does not contain extra data. In our scenario server thread has dequeued and started processing the hence we see it in the LpcDataInfoChainHead.
We now dump the server thread to see why it has not responded to the message for 12mins.
0: kd> .process /p /r 896e1450
Implicit process is now 896e1450
............................................................................................................................
0: kd> !thread 89531020
THREAD 89531020 Cid 03f4.10a0 Teb: 7ffac000 Win32Thread: 00000000 WAIT: (WrLpcReply) UserMode Non-Alertable
8953120c Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0003923d:
Current LPC port e22d29d8
Impersonation token: e15315d0 (Level Impersonation)
Owning Process 896e1450 Image: svchost1.exe
Wait Start TickCount 144629 Ticks: 2027 (0:00:00:31.671)
Context Switch Count 219
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x00039236
LPC Server thread working on message Id 39236
Stack Init b8d07000 Current b8d06c08 Base b8d07000 Limit b8d04000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
b8d06c20 8083e6a2 89531098 89531020 895310c8 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b8d06c4c 8083f164 8953120c 895311e0 89531020 nt!KiSwapThread+0x284 (FPO: [Non-Fpo])
b8d06c94 8093983f 8953120c 00000011 b8d06d01 nt!KeWaitForSingleObject+0x346 (FPO: [Non-Fpo])
b8d06d50 80834d3f 0000056c 000f3fc0 000f3fc0 nt!NtRequestWaitReplyPort+0x776 (FPO: [Non-Fpo])
b8d06d50 7c82ed54 0000056c 000f3fc0 000f3fc0 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b8d06d64)
0097f0a8 7c821c94 77c72700 0000056c 000f3fc0 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
0097f0ac 77c72700 0000056c 000f3fc0 000f3fc0 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])
0097f118 77c713ba 0097f154 0097f138 77c72c7f RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [Non-Fpo])
0097f124 77c72c7f 0097f154 76d320d8 0097f540 RPCRT4!I_RpcSendReceive+0x24 (FPO: [Non-Fpo])
0097f138 77ce219b 0097f180 000db5f8 00000000 RPCRT4!NdrSendReceive+0x2b (FPO: [Non-Fpo])
0097f520 76d41213 76d320d8 76d402c8 0097f540 RPCRT4!NdrClientCall2+0x22e (FPO: [Non-Fpo])
0097f538 76d3fc12 000b5618 000ce248 000ce268 rpcss!LocalCreateInstance+0x1c (FPO: [Non-Fpo])
0097f5cc 76d3f033 0097f7d8 0097f654 0097f824 rpcss!CServerListEntry::CallServer+0x127 (FPO: [Non-Fpo])
0097f604 76d3bc7f 00000001 00000008 00000000 rpcss!CServerTableEntry::CallRunningServer+0x181 (FPO: [Non-Fpo])
0097f670 76d3bac5 0097f7d8 00000000 000e415c rpcss!Activation+0x337 (FPO: [Non-Fpo])
0097f6cc 76d3dd08 000e415c 0097f7bc 0097f71c rpcss!ActivateFromProperties+0x213 (FPO: [Non-Fpo])
0097f6dc 76d3dd5c 76d738d0 00000000 000e415c rpcss!CScmActivator::CreateInstance+0x10 (FPO: [Non-Fpo])
0097f71c 76d3c162 000e415c 00000000 0097f7bc rpcss!ActivationPropertiesIn::DelegateCreateInstance+0xf7 (FPO: [Non-Fpo])
0097f764 76d3bdb6 000e415c 0097f7bc 00000000 rpcss!ActivateFromPropertiesPreamble+0x4e3 (FPO: [Non-Fpo])
0097f7ac 76d3dcdd 00000002 000ce2ac 00000000 rpcss!PerformScmStage+0xbb (FPO: [Non-Fpo])
0097f8c8 77c70f3b 000cdbb0 000ce248 000ce268 rpcss!SCMActivatorCreateInstance+0xa2 (FPO: [Non-Fpo])
0097f8f8 77ce23f7 76d3dc3e 0097fae0 00000007 RPCRT4!Invoke+0x30
0097fcf8 77ce26ed 00000000 00000000 000cdcdc RPCRT4!NdrStubCall2+0x299 (FPO: [Non-Fpo])
0097fd14 77c709be 000cdcdc 00094ef0 000cdcdc RPCRT4!NdrServerCall2+0x19 (FPO: [Non-Fpo])
0097fd48 77c7093f 76d3156c 000cdcdc 0097fdec RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [Non-Fpo])
0097fd9c 77c70865 00000004 00000000 76d73538 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x117 (FPO: [Non-Fpo])
0097fdc0 77c734b1 000cdcdc 00000000 76d73538 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [Non-Fpo])
0097fdfc 77c71bb3 000b44d8 0008f0e8 000dea40 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0x42c (FPO: [Non-Fpo])
0097fe20 77c75458 0008f120 0097fe38 000b44d8 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0x127 (FPO: [Non-Fpo])
0097ff84 77c5778f 0097ffac 77c5f7dd 0008f0e8 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x430 (FPO: [Non-Fpo])
0097ff8c 77c5f7dd 0008f0e8 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd (FPO: [Non-Fpo])
0097ffac 77c5de88 00084298 0097ffec 77e6608b RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [Non-Fpo])
0097ffb8 77e6608b 000c0070 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [Non-Fpo])
0097ffec 00000000 77c5de6d 000c0070 00000000 kernel32!BaseThreadStart+0x34 (FPO: [Non-Fpo])
The server thread is waiting for a reply to another LPC message it issued while servicing the client request. Tracing the LPC message as above -
0: kd> !lpc message 0003923d
Searching message 3923d in threads ...
Client thread 89531020 waiting a reply from 3923d
Server thread 898cd998 is working on message 3923d
Searching thread 89531020 in port rundown queues ...
Server communication port 0xe22d58c8
Connected port: 0xe22d29d8 Server connection port: 0xe17a95f8
Client communication port 0xe22d29d8
Handles: 1 References: 15
Server connection port e17a95f8 Name: OLE71892D01F993498EA1C3757C71D5
Handles: 1 References: 37
Server process : 89bedd88 (svchost.exe)
Queue semaphore : 89718210
0000 e188c3b0 - Busy Id=00039239 From: 03f4.111c Context=80030001 [e17a9678 . e28b00f8]
Data: 00000001 00040342 0000d401 000004a8 2e6c8db6 4131cb31
0000 e28b00f8 - Busy Id=0003923d From: 03f4.10a0 Context=80030001 [e188c3b0 . e2846008]
0000 e2846008 - Busy Id=0003c96e From: 03f4.0df0 Context=80030001 [e28b00f8 . e27dcb70]
0000 e27dcb70 - Busy Id=0003db3c From: 03f4.1158 Context=80030001 [e2846008 . e28c0788]
0000 e28c0788 - Busy Id=0003db41 From: 03f4.0fbc Context=80030001 [e27dcb70 . e2983650]
0000 e2983650 - Busy Id=0003db5c From: 03f4.0f40 Context=80030001 [e28c0788 . e2596ae0]
0000 e2596ae0 - Busy Id=00046180 From: 03f4.03d8 Context=80030001 [e2983650 . e28c3ea0]
0000 e28c3ea0 - Busy Id=0004a38d From: 03f4.07c4 Context=80030001 [e2596ae0 . e294aea0]
0000 e294aea0 - Busy Id=0004d0c6 From: 03f4.1714 Context=80030001 [e28c3ea0 . e2977ea0]
Data: 00000001 00030342 0000d401 000004a8 2e6c8db6 4131cb31
0000 e2977ea0 - Busy Id=000544d8 From: 03f4.162c Context=80030001 [e294aea0 . e241f008]
0000 e241f008 - Busy Id=0006077e From: 03f4.031c Context=80030001 [e2977ea0 . e2940820]
0000 e2940820 - Busy Id=000638da From: 03f4.1754 Context=80030001 [e241f008 . e2576270]
0000 e2576270 - Busy Id=000638f1 From: 03f4.1794 Context=80030001 [e2940820 . e261c268]
0000 e261c268 - Busy Id=000638fe From: 03f4.17a8 Context=80030001 [e2576270 . e17a9678]
The LpcDataInfoChainHead queue contains 14 messages
Threads in RunDown queue : 0xe188c1f0 0xe28aff38 0xe2845e48 0xe27dc9b0 0xe28c05c8 0xe2983490 0xe2596920 0xe28c3ce0 0xe294ace0 0xe2977ce0 0xe241ee48 0xe2940660 0xe25760b0 0xe261c0a8
0: kd> .process /p /r 89bedd88
Implicit process is now 89bedd88
0: kd> !thread 898cd998
THREAD 898cd998 Cid 04a8.0508 Teb: 7ffd5000 Win32Thread: e23a6008 WAIT: (UserRequest) UserMode Non-Alertable
89006340 SynchronizationEvent
IRP List:
88eb89e0: (0006,0094) Flags: 00000800 Mdl: 00000000
Owning Process 89bedd88 Image: svchost.exe
Context Switch Count 7330 LargeStack
UserTime 00:00:00.906
KernelTime 00:00:00.531
Win32 Start Address 0x0003923d
LPC Server thread working on message Id 3923d
Stack Init b9a55000 Current b9a54c60 Base b9a55000 Limit b9a51000 Call 0
b9a54c78 8083e6a2 898cda10 898cd998 898cda40 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b9a54ca4 8083f164 00000000 00000000 00000000 nt!KiSwapThread+0x284 (FPO: [Non-Fpo])
b9a54cec 8092db70 89006340 00000006 80834d01 nt!KeWaitForSingleObject+0x346 (FPO: [Non-Fpo])
b9a54d50 80834d3f 00000d64 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [Non-Fpo])
b9a54d50 7c82ed54 00000d64 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b9a54d64)
0109f248 7c822124 77e6bad8 00000d64 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
0109f24c 77e6bad8 00000d64 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])
0109f2bc 77e6ba42 00000d64 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac (FPO: [Non-Fpo])
0109f2d0 77719486 00000d64 ffffffff 00000000 kernel32!WaitForSingleObject+0x12 (FPO: [Non-Fpo])
0109f2e4 7769c09b 00086803 00000000 00086660 ole32!CComApartment::WaitForAccess+0x5c (FPO: [0,0,0])
0109f2f8 776a417d 0109f344 02163088 02145ac0 ole32!CComApartment::GetPreRegMOID+0x41 (FPO: [Non-Fpo])
0109f310 776a40d2 0109f344 77790858 00000001 ole32!GetPreRegMOID+0x24 (FPO: [Non-Fpo])
0109f358 776a48e3 00000001 00000003 0109f3c4 ole32!CIDObject::GetOrCreateStdID+0x11e (FPO: [Non-Fpo])
0109f37c 776a4419 02163088 00000000 00086860 ole32!ObtainStdIDFromUnk+0x92 (FPO: [Non-Fpo])
0109f3a4 776a43c1 0109f468 00162690 02b8bd30 ole32!StdMarshalObject+0x49 (FPO: [Non-Fpo])
0109f400 776a3974 0109f42c 0109f468 00162690 ole32!CDestObjectWrapper::MarshalInterface+0x150 (FPO: [Non-Fpo])
0109f43c 77686f83 0109f468 00162690 02b8bd30 ole32!CoMarshalInterface+0x93 (FPO: [Non-Fpo])
0109f490 77686e38 02b8bd30 00162690 00162690 ole32!MarshalHelperMulti+0x48 (FPO: [Non-Fpo])
0109f4bc 77686d46 58b10040 00000001 00162690 ole32!GetInstanceHelperMulti+0x4d (FPO: [Non-Fpo])
0109f584 77c70f3b 000a7938 00000000 0218b774 ole32!CObjServer::CreateInstance+0x30d (FPO: [Non-Fpo])
0109f5a8 77ce23f7 77686b34 0109f790 00000004 RPCRT4!Invoke+0x30
0109f9a8 77ce1a95 000b4398 000b2074 05cc596c RPCRT4!NdrStubCall2+0x299 (FPO: [Non-Fpo])
0109fa00 77788ec1 000b4398 05cc596c 000b2074 RPCRT4!CStdStubBuffer_Invoke+0xc6 (FPO: [Non-Fpo])
0109fa44 77788e74 05cc596c 000b4428 00000000 ole32!SyncStubInvoke+0x33 (FPO: [Non-Fpo])
0109fa8c 7769b2b7 05cc596c 000b4288 000b4398 ole32!StubInvoke+0xa7 (FPO: [Non-Fpo])
0109fb64 7769b0b5 000b2074 00000000 000b4398 ole32!CCtxComChnl::ContextInvoke+0xe3 (FPO: [Non-Fpo])
0109fb80 77789926 05cc596c 00000001 000b4398 ole32!MTAInvoke+0x1a (FPO: [Non-Fpo])
0109fbb0 77788c33 d0908070 000b2074 000b4398 ole32!AppInvoke+0xa3 (FPO: [Non-Fpo])
0109fc84 77789936 05cc5918 000b22f8 000b4410 ole32!ComInvokeWithLockAndIPID+0x2c5 (FPO: [Non-Fpo])
0109fcd0 77c709be 020ccc24 000b4410 020ccc24 ole32!ThreadInvoke+0x1e0 (FPO: [Non-Fpo])
0109fd04 77c7093f 777887e0 020ccc24 0109fdec RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [Non-Fpo])
0109fd58 77c70865 00000000 00000000 7767bfa8 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x117 (FPO: [Non-Fpo])
0109fd7c 77c657eb 020ccc24 00000000 7767bfa8 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [Non-Fpo])
0109fdbc 77c71e26 020ccc24 020ccbdc 00000000 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xc0 (FPO: [Non-Fpo])
0109fdfc 77c71bb3 000c7db0 000b1498 00097c08 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0x42c (FPO: [Non-Fpo])
0109fe20 77c75458 000b14d0 0109fe38 000c7db0 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0x127 (FPO: [Non-Fpo])
0109ff84 77c5778f 0109ffac 77c5f7dd 000b1498 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x430 (FPO: [Non-Fpo])
0109ff8c 77c5f7dd 000b1498 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd (FPO: [Non-Fpo])
0109ffac 77c5de88 0008aa48 0109ffec 77e6608b RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [Non-Fpo])
0109ffb8 77e6608b 000b1678 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [Non-Fpo])
The above LPC server thread is waiting for allocation of COM OID (Object Identifier) since we have run out of OIDs. The way OIDs are allocated is by calling CComApartment::CallTheResolver( ). Searching threads in the system with CComApartment::CallTheResolver on the stack we get the below thread within svchost.exe.
0: kd> !thread 88d76db0
THREAD 88d76db0 Cid 04a8.13f4 Teb: 7ffd6000 Win32Thread: e295c758 WAIT: (Unknown) UserMode Non-Alertable
88d76f9c Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0003832f:
Current LPC port e15791b8
Wait Start TickCount 99073 Ticks: 47583 (0:00:12:23.484)
Context Switch Count 6947 LargeStack
UserTime 00:00:00.859
KernelTime 00:00:00.562
Win32 Start Address 0x0003832e
LPC Server thread working on message Id 3832e
Stack Init b8af6000 Current b8af5c08 Base b8af6000 Limit b8af2000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
b8af5c20 8083e6a2 88d76e28 88d76db0 88d76e58 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b8af5c4c 8083f164 88d76f9c 88d76f70 88d76db0 nt!KiSwapThread+0x284 (FPO: [Non-Fpo])
b8af5c94 8093983f 88d76f9c 00000011 b8af5d01 nt!KeWaitForSingleObject+0x346 (FPO: [Non-Fpo])
b8af5d50 80834d3f 00000094 000dde10 000dde10 nt!NtRequestWaitReplyPort+0x776 (FPO: [Non-Fpo])
b8af5d50 7c82ed54 00000094 000dde10 000dde10 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b8af5d64)
0251ed2c 7c821c94 77c72700 00000094 000dde10 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
0251ed30 77c72700 00000094 000dde10 000dde10 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])
0251ed88 77c713ba 0251edc4 0251eda8 77c72c7f RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [Non-Fpo])
0251ed94 77c72c7f 0251edc4 776720f8 0251f1b0 RPCRT4!I_RpcSendReceive+0x24 (FPO: [Non-Fpo])
0251eda8 77ce219b 0251edf0 05c6b44c 0251f360 RPCRT4!NdrSendReceive+0x2b (FPO: [Non-Fpo])
0251f190 7769c087 776720f8 77671df0 0251f1b0 RPCRT4!NdrClientCall2+0x22e (FPO: [Non-Fpo])
0251f1a8 7769c04e 0008b0a8 0008bc30 0251f1f4 ole32!ServerAllocateOIDs+0x1c (FPO: [Non-Fpo])
0251f1d8 7769c01b 0251f1f4 0251f368 0251f220 ole32!CRpcResolver::ServerAllocOIDs+0x2a (FPO: [Non-Fpo])
0251f1fc 7769bf93 0251f368 0251f220 00000014 ole32!OXIDEntry::AllocOIDs+0x40 (FPO: [Non-Fpo])
0251f36c 7769c0b2 00086803 00000000 00086660 ole32!CComApartment::CallTheResolver+0x6b (FPO: [Non-Fpo])
0251f380 776a417d 0251f3cc 05c67490 05d59ee0 ole32!CComApartment::GetPreRegMOID+0x54 (FPO: [Non-Fpo])
0251f398 776a40d2 0251f3cc 77790858 00000001 ole32!GetPreRegMOID+0x24 (FPO: [Non-Fpo])
0251f3e0 776a48e3 00000001 00000003 0251f44c ole32!CIDObject::GetOrCreateStdID+0x11e (FPO: [Non-Fpo])
0251f404 776a4419 05c67490 00000000 00086860 ole32!ObtainStdIDFromUnk+0x92 (FPO: [Non-Fpo])
0251f42c 776a43c1 05e39b00 0251f504 02b30234 ole32!StdMarshalObject+0x49 (FPO: [Non-Fpo])
0251f488 776a3974 0251f4b4 05e39b00 0251f504 ole32!CDestObjectWrapper::MarshalInterface+0x150 (FPO: [Non-Fpo])
0251f4c4 77c544a3 05e39b00 0251f504 02b30234 ole32!CoMarshalInterface+0x93 (FPO: [Non-Fpo])
0251f518 77c54e85 0251f5e8 02b30234 74ce6210 RPCRT4!NdrpInterfacePointerMarshall+0x9a (FPO: [Non-Fpo])
0251f538 77c691ad 0251f5e8 000f2898 02b30234 RPCRT4!NdrpPointerMarshall+0x87 (FPO: [Non-Fpo])
0251f550 77c690fc 0251f5e8 02b30234 74ce6210 RPCRT4!NdrPointerMarshall+0x30 (FPO: [Non-Fpo])
0251f570 77c691ad 0251f5e8 00000000 00112e50 RPCRT4!NdrpPointerMarshall+0x116 (FPO: [Non-Fpo])
0251f588 77c715ac 0251f5e8 00112e50 74ce620c RPCRT4!NdrPointerMarshall+0x30 (FPO: [Non-Fpo])
0251f5ac 77ce249e 00000000 00000001 020ce8c8 RPCRT4!NdrpServerMarshal+0x82 (FPO: [Non-Fpo])
0251f9a8 77ce1a95 020ce8c8 0011fa08 000f1454 RPCRT4!NdrStubCall2+0x374 (FPO: [Non-Fpo])
0251fa00 77788ec1 020ce8c8 000f1454 0011fa08 RPCRT4!CStdStubBuffer_Invoke+0xc6 (FPO: [Non-Fpo])
0251fa44 77788e74 000f1454 00137868 020debf0 ole32!SyncStubInvoke+0x33 (FPO: [Non-Fpo])
0251fa8c 7769b2b7 000f1454 0014aaf8 020ce8c8 ole32!StubInvoke+0xa7 (FPO: [Non-Fpo])
0251fb64 7769b0b5 0011fa08 00000000 020ce8c8 ole32!CCtxComChnl::ContextInvoke+0xe3 (FPO: [Non-Fpo])
0251fb80 77789926 000f1454 00000001 020ce8c8 ole32!MTAInvoke+0x1a (FPO: [Non-Fpo])
0251fbb0 77788c33 d0908070 0011fa08 020ce8c8 ole32!AppInvoke+0xa3 (FPO: [Non-Fpo])
0251fc84 77789936 000f1400 020d3b48 00137850 ole32!ComInvokeWithLockAndIPID+0x2c5 (FPO: [Non-Fpo])
0251fcd0 77c709be 0216202c 00137850 0216202c ole32!ThreadInvoke+0x1e0 (FPO: [Non-Fpo])
0251fd04 77c7093f 777887e0 0216202c 0251fdec RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [Non-Fpo])
0251fd58 77c70865 00000000 00000000 7767bfa8 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x117 (FPO: [Non-Fpo])
0251fd7c 77c657eb 0216202c 00000000 7767bfa8 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [Non-Fpo])
0: kd> !lpc message 0003832f
Searching message 3832f in threads ...
Server thread 8900edb0 is working on message 3832f
Client thread 88d76db0 waiting a reply from 3832f
Searching thread 88d76db0 in port rundown queues ...
Server communication port 0xe188a6e8
Connected port: 0xe15791b8 Server connection port: 0xe13734b0
Client communication port 0xe15791b8
Handles: 1 References: 5
0: kd> !thread 8900edb0
THREAD 8900edb0 Cid 03f4.0598 Teb: 7ffd4000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
89014cc0 NotificationEvent
Context Switch Count 5892
UserTime 00:00:00.765
KernelTime 00:00:01.203
Win32 Start Address 0x0003832f
LPC Server thread working on message Id 3832f
Stack Init b95d1000 Current b95d0c60 Base b95d1000 Limit b95ce000 Call 0
b95d0c78 8083e6a2 8900ee28 8900edb0 8900ee58 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b95d0ca4 8083f164 00000000 00000000 00000000 nt!KiSwapThread+0x284 (FPO: [Non-Fpo])
b95d0cec 8092db70 89014cc0 00000006 80935d01 nt!KeWaitForSingleObject+0x346 (FPO: [Non-Fpo])
b95d0d50 80834d3f 000004e8 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [Non-Fpo])
b95d0d50 7c82ed54 000004e8 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ b95d0d64)
0082f7a4 7c822124 77e6bad8 000004e8 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])
0082f7a8 77e6bad8 000004e8 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])
0082f818 77e6ba42 000004e8 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac (FPO: [Non-Fpo])
0082f82c 77cab1e0 000004e8 ffffffff 000bc314 kernel32!WaitForSingleObject+0x12 (FPO: [Non-Fpo])
0082f840 77cab333 0082f89c 000ad626 000bc314 RPCRT4!SWMRLock::LockSharedOrExclusiveOnLastWriter+0x32 (FPO: [Non-Fpo])
0082f868 77c72e00 0082f89c 00000001 00000002 RPCRT4!SWMRLock::LockSharedOrExclusive+0xa6 (FPO: [Non-Fpo])
0082f890 77c72f71 00000000 00000000 00000010 RPCRT4!NDRSContextUnmarshall2+0x1b9 (FPO: [Non-Fpo])
0082f8bc 77c72eb6 4182f938 76d32c22 0082f938 RPCRT4!NdrServerContextNewUnmarshall+0xa6 (FPO: [Non-Fpo])
0082f8d0 77c70f93 0082f938 0082fae4 76d32c22 RPCRT4!NdrUnmarshallHandle+0x52 (FPO: [Non-Fpo])
0082f900 77ce2345 0082fae4 00094618 00000000 RPCRT4!NdrpServerUnMarshal+0x13d (FPO: [Non-Fpo])
0082fcf8 77ce26ed 00000000 00000000 000bbd9c RPCRT4!NdrStubCall2+0x19f (FPO: [Non-Fpo])
0082fd14 77c709be 000bbd9c 00094618 000bbd9c RPCRT4!NdrServerCall2+0x19 (FPO: [Non-Fpo])
0082fd48 77c7093f 76d3156c 000bbd9c 0082fdec RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [Non-Fpo])
0082fd9c 77c70865 00000005 00000000 76d736c0 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x117 (FPO: [Non-Fpo])
0082fdc0 77c734b1 000bbd9c 00000000 76d736c0 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [Non-Fpo])
0082fdfc 77c71bb3 00099188 0008f0e8 000adfd8 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0x42c (FPO: [Non-Fpo])
0082fe20 77c75458 0008f120 0082fe38 00099188 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0x127 (FPO: [Non-Fpo])
0082ff84 77c5778f 0082ffac 77c5f7dd 0008f0e8 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x430 (FPO: [Non-Fpo])
0082ff8c 77c5f7dd 0008f0e8 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd (FPO: [Non-Fpo])
0082ffac 77c5de88 00084298 0082ffec 77e6608b RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [Non-Fpo])
0082ffb8 77e6608b 000bc298 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [Non-Fpo])
0082ffec 00000000 77c5de6d 000bc298 00000000 kernel32!BaseThreadStart+0x34 (FPO: [Non-Fpo])
The above thread belongs to the RPC service and is waiting for a lock to be acquired.
0: kd> x /v svchost1!*service*name*
pub global 01004078 0 svchost1!ServiceNames = <no type information>
0: kd> du poi(01004078)
000839f8 "RpcSs"
To find why this thread is not able to acquire the lock, investigation of the threads within the RPC service is required. The reason the lock is not available is because there is a thread that has acquired the lock and is trying to reach a client that does not exist.
The chain of events is summarized in the below figure. Note that all horizontal links were traversed using LPC data structures and debugger extensions. The vertical links were traversed by investigation beyond the scope of LPC. Thus the issue that started in a component of SMS was finally traced to RPC through the use of LPC data structures and debugger extension. LPC is one of the core inter-process communication mechanisms. Understanding LPC and learning to use its extensions helps a lot to debug issues where client threads are waiting for reply from the server.
Thanks for this great article !
PingBack from http://mdavey.wordpress.com/2007/09/12/agile-pain-wpf-and-more/
Hi,
really a fantastic article! Please more from this kind! I like the insights into the OS!
Regards,
Dominik
Great article with great helpful