Long COM+ Call times Windows debugging

COM+ debugging에서 worker process의 hang 현상에 대한 내용입니다.

먼저, COM+ Application이 hang이라고 느껴지면, 무엇보다도 hang이 된 동안 2~3차례 메모리 덤프를 수집하게 됩니다. 

* NOTE: 메모리 덤프 수집에 대한 것은 다음의 문서를 참조하십시오.

ADPlus is a tool from Microsoft Product Support Services (PSS) that can troubleshoot any process or application that stops responding (hangs) or fails (crashes). Frequently, you can use ADPlus (ADPlus ...

support.microsoft.com/default.aspx?scid=kb;en-us;286350 2005-12-31
 
Debugging Tools for windows에서 제공하는 cdb.exe 를 이용한 script인 AD+(adplus.vbs)를 이용하여,
 
adplus -hang -p <pid>
 
와 같이 간단한 Commmand로 메모리 덤프를 수집할 수 있다. ***
 
첫번째 고려해야할 사항은 2 ~3 차례 Dumps 의 threads 들의 Callstack을 살펴보는 것입니다. 코드의 Loop가 존재할 수 있기 때문입니다.
 
두번째 고려해야 할 사항은 !locks 또는 sieextpub.dll (debugger extension입니다.)에서 제공하는 
  !critlist            = List CritSecs that threads are waiting on
!waitlist            = Lists handles each thread is blocking on

를 확인해 보는 것입니다. 이는 critical section이나 blocking 상태의 정보를 얻을 수 있습니다.
 
세번째 고려해야할 사항은 해당 덤프의 특정 thread가 다른 Process를 call하고 그에 대한 응답을 기다릴 수 있습니다. 그러므로, 이때 중요한 사항은 어떤  Process를 기다리고 있느냐를 찾는 것이 문제해결에 도움이 될 수 있습니다. 이 경우는 sieextpub.dll에서 제공하는 !comcalls가 도움이 될 것 입니다. 
 
 
  1. Load the SieExtPub extension.
    .load sieextpub.dll
  2. Run the comcalls command.
    !sieextpub.comcalls
    Sample output:
    Thread 7 – MTA
    Target Process ID: 00000654 = 1620
    Target Thread ID: ffffffff (NTA)
    Thread 14 – MTA
    Target Process ID: 00000520 = 1312
    Target Thread ID: ffffffff (NTA)
    Thread 22 – STA
    Target Process ID: 000009cc = 2508
    Target Thread ID: 00000a0c (STA)
  
반드시 상위와 같이 좋은 결과만 얻게 되지는 않습니다.

0:026> !comcalls
Thread 1 - MTA
Target Process ID: 2ffc1f9c = 805052316
Target Thread  ID: 520e2081  (STA - Possible junk values)
Thread 7 - MTA
Target Process ID: 28f81f9c = 687349660
Target Thread  ID: dac27bb6  (STA - Possible junk values)
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for sleep.dll -
Thread 19 - MTA
Target Process ID: 14401f9c = 339746716
Target Thread  ID: 886266a3  (STA - Possible junk values)
Thread 23 - MTA
Target Process ID: 25ac1f9c = 632037276
Target Thread  ID: df95ca8a  (STA - Possible junk values)
 Thread 24 - MTA
Target Process ID: 24381f9c = 607657884
Target Thread  ID: cdb39f8a  (STA - Possible junk values)
Thread 25 - MTA
Target Process ID: 2fb01f9c = 800071580
Target Thread  ID: eb063d86  (STA - Possible junk values)

 
상위의 결과는 24번 Thread가 이상한 Process ID정보(24381f9c)를 가지고 있습니다. 24번 Thread의 callstack은 다음과 같습니다.
 
0:024> kb
ChildEBP RetAddr  Args to Child             
017decb8 7c90e9c0 7c8025db 00000494 00000000 ntdll!KiFastSystemCallRet
017decbc 7c8025db 00000494 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
017ded20 7c802542 00000494 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xa8
017ded34 775273a5 00000494 ffffffff 000a23b8 kernel32!WaitForSingleObject+0x12
017ded50 77601e51 000a23b8 000fc7b0 00000000 ole32!GetToSTA+0x6f
017ded70 7760109a 017dee38 017def48 000d9b14 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xf6
017dee50 77523c64 000d9b14 017def48 017def38 ole32!CRpcChannelBuffer::SendReceive2+0xb9
017deebc 77523bfc 000d9b14 017def48 017def38 ole32!CAptRpcChnl::SendReceive+0xab
017def10 77ef3db5 000d9b14 017def48 017def38 ole32!CCtxComChnl::SendReceive+0x113
017def2c 77ef3eac 000d6fcc 017def74 0600015b rpcrt4!NdrProxySendReceive+0x43
017df308 77ef3e42 774e6218 774e938a 017df340 rpcrt4!NdrClientCall2+0x1fa
017df328 77e89aa4 00000014 00000004 017df358 rpcrt4!ObjectStublessClient+0x8b
017df338 77520369 000d6fcc 00000000 000fd74c rpcrt4!ObjectStubless+0xf
017df358 7752112b 000d6fcc 00000001 00000000 ole32!CProcessActivator::CCICallback+0x6d
017df378 775210e2 7760714c 000fd5a8 00000000 ole32!CProcessActivator::AttemptActivation+0x2c
017df3b0 77520453 7760714c 000fd5a8 00000000 ole32!CProcessActivator::ActivateByContext+0x42
017df3d8 77520143 7760714c 00000000 000fd74c ole32!CProcessActivator::CreateInstance+0x49
017df418 766858d4 000fd74c 00000000 000f4c88 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
017df484 77520143 000e8c50 00000000 000fd74c comsvcs!CSTAPoolActivator::CreateInstance+0x491
017df4c4 76675e13 000fd74c 00000000 000f4c88 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7



SendReceive2 함수의 첫번째 parameter는 ProcessID와 ThreadID의 Hint를 가지고 있습니다.
 
0:024> dc 000d9b14
000d9b14  774e2328 774e22f8 00000003 0000002a  (#Nw."Nw....*...
000d9b24  000dbb98 00000000 000a23b8 000dac90  .........#......
000d9b34  000a8200 000dbe18 774e1930 00070005  ........0.Nw....
000d9b44  00000003 00002438 00000000 774e2328  ....8$......(#Nw
000d9b54  774e22f8 00000001 00000024 00000000  ."Nw....$.......
000d9b64  00000000 000a23b8 00000000 00000000  .....#..........
000d9b74  000dd720 774e1930 00070005 ffffffff   ...0.Nw........
000d9b84  00002438 00002438 774e2328 774e22f8  8$..8$..(#Nw."Nw
0:024> dc 000a23b8
000a23b8  000c5480 000a2340 00001f9c 00002438 
.T..@#......8$..
000a23c8  ce805af0 c37b151e 6ab661eb fcfdf8d2  .Z....{..a.j....
000a23d8  6ab661eb fcfdf8d2 00008c14 24381f9c  .a.j..........8$
000a23e8  cdb39f8a 578be980 00000103 0057019e  .......W......W.
000a23f8  000c4c98 00000000 00000000 00000000  .L..............
000a2408  00000001 ffffffff 000a1ed8 000bd17c  ............|...
000a2418  00000009 00000000 00000001 00000000  ................
000a2428  00000000 00070005 0097001d 0008010a  ................



해당 ProcessID는 1f9c 입니다. 그래서, 찾아 보았습니다. 해당 Process와 Thread를 ..

0:024> ~
  0  Id: 1f9c.1fc0 Suspend: 1 Teb: 7ffdd000 Unfrozen
  1  Id: 1f9c.1f0c Suspend: 1 Teb: 7ffdc000 Unfrozen
  2  Id: 1f9c.22f4 Suspend: 1 Teb: 7ffdb000 Unfrozen
  3  Id: 1f9c.664 Suspend: 1 Teb: 7ffda000 Unfrozen
  4  Id: 1f9c.142c Suspend: 1 Teb: 7ffd8000 Unfrozen
  5  Id: 1f9c.1194 Suspend: 1 Teb: 7ffd7000 Unfrozen
  6  Id: 1f9c.1078 Suspend: 1 Teb: 7ffd6000 Unfrozen
  7  Id: 1f9c.136c Suspend: 1 Teb: 7ffd9000 Unfrozen
  8  Id: 1f9c.253c Suspend: 1 Teb: 7ffd4000 Unfrozen
  9  Id: 1f9c.928 Suspend: 1 Teb: 7ffaf000 Unfrozen
10  Id: 1f9c.1eec Suspend: 1 Teb: 7ffae000 Unfrozen
11  Id: 1f9c.1440 Suspend: 1 Teb: 7ffad000 Unfrozen
12  Id: 1f9c.2ffc Suspend: 1 Teb: 7ffac000 Unfrozen
13  Id: 1f9c.28f8 Suspend: 1 Teb: 7ffab000 Unfrozen
14  Id: 1f9c.25ac Suspend: 1 Teb: 7ffaa000 Unfrozen
15  Id: 1f9c.2438 Suspend: 1 Teb: 7ffa9000 Unfrozen
  16  Id: 1f9c.2fb0 Suspend: 1 Teb: 7ffa8000 Unfrozen
17  Id: 1f9c.2b64 Suspend: 1 Teb: 7ffa7000 Unfrozen
18  Id: 1f9c.11dc Suspend: 1 Teb: 7ffa6000 Unfrozen
19  Id: 1f9c.18b4 Suspend: 1 Teb: 7ffa5000 Unfrozen
20  Id: 1f9c.28a0 Suspend: 1 Teb: 7ffd5000 Unfrozen
21  Id: 1f9c.15e4 Suspend: 1 Teb: 7ffa4000 Unfrozen
22  Id: 1f9c.1f20 Suspend: 1 Teb: 7ffa3000 Unfrozen
23  Id: 1f9c.2b18 Suspend: 1 Teb: 7ffa2000 Unfrozen
. 24  Id: 1f9c.2a10 Suspend: 1 Teb: 7ffa1000 Unfrozen
25  Id: 1f9c.1804 Suspend: 1 Teb: 7ffa0000 Unfrozen
# 26  Id: 1f9c.2798 Suspend: 1 Teb: 7ff9f000 Unfrozen


Callstack은 다음과 같습니다. kernel32!SleepEx 함수가 호출되고 있습니다.

0:015> kb
ChildEBP RetAddr  Args to Child             
00e8eb60 7c90d85c 7c8023ed 00000000 00e8eb94 ntdll!KiFastSystemCallRet
00e8eb64 7c8023ed 00000000 00e8eb94 00e8f4f0 ntdll!NtDelayExecution+0xc
00e8ebbc 7c802451 00007530 00000000 00e8ec00 kernel32!SleepEx+0x61
00e8ebcc 11001924 00007530 00e8f4f0 000da710 kernel32!Sleep+0xf

WARNING: Stack unwind information not available. Following frames may be wrong.
00e8ec00 771273d0 000d7250 000da708 00000000 sleep!DllCanUnloadNow+0x62
00e8ec1c 7344a2fb 000d7250 0000001c 00000004 oleaut32!DispCallFunc+0x16a
00e8f578 7344a0f4 000d7250 110012c4 60030000 msvbvm60!EpiInvokeMethod+0x5a3
00e8f5d4 7719bf39 000d7250 60030000 000dd854 msvbvm60!BASIC_CLASS_Invoke+0x64
00e8f608 7719b1bd 000d7250 60030000 000dd854 oleaut32!IDispatch_Invoke_Stub+0x52
00e8f644 77ef4047 00e8f6b0 000d7250 60030000 oleaut32!IDispatch_RemoteInvoke_Thunk+0x34
00e8fa68 77ef3bf3 000d6668 000d9b50 000d74c4 rpcrt4!NdrStubCall2+0x212
00e8fac0 7717e529 000d6668 000d74c4 000d9b50 rpcrt4!CStdStubBuffer_Invoke+0xc6
00e8fae0 77600c31 000dbf10 000d74c4 000d9b50 oleaut32!CStubWrapper::Invoke+0x9f
00e8fb20 77600bdb 000d74c4 000d18c8 000b8b44 ole32!SyncStubInvoke+0x33
00e8fb68 77522a22 000d74c4 000dd720 000dbf10 ole32!StubInvoke+0xa7
00e8fc40 77522947 000d9b50 00000000 000dbf10 ole32!CCtxComChnl::ContextInvoke+0xe3
00e8fc5c 77523461 000d74c4 00000001 000dbf10 ole32!MTAInvoke+0x1a
00e8fc88 77600e3b 000d74c4 00000001 000dbf10 ole32!STAInvoke+0x4a
00e8fcbc 776009bc 000d7470 000d9b50 000dbf10 ole32!AppInvoke+0x7e
00e8fd90 77600df2 000d7470 000dad80 00000400 ole32!ComInvokeWithLockAndIPID+0x2e0


그럼, 누가 Thread를 Invoke 했을 까요?

0:024> kb 200
ChildEBP RetAddr  Args to Child             
017decb8 7c90e9c0 7c8025db 00000494 00000000 ntdll!KiFastSystemCallRet
017decbc 7c8025db 00000494 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
017ded20 7c802542 00000494 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xa8
017ded34 775273a5 00000494 ffffffff 000a23b8 kernel32!WaitForSingleObject+0x12
017ded50 77601e51 000a23b8 000fc7b0 00000000 ole32!GetToSTA+0x6f
017ded70 7760109a 017dee38 017def48 000d9b14 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xf6
017dee50 77523c64 000d9b14 017def48 017def38 ole32!CRpcChannelBuffer::SendReceive2+0xb9
017deebc 77523bfc 000d9b14 017def48 017def38 ole32!CAptRpcChnl::SendReceive+0xab
017def10 77ef3db5 000d9b14 017def48 017def38 ole32!CCtxComChnl::SendReceive+0x113
017def2c 77ef3eac 000d6fcc 017def74 0600015b rpcrt4!NdrProxySendReceive+0x43
017df308 77ef3e42 774e6218 774e938a 017df340 rpcrt4!NdrClientCall2+0x1fa
017df328 77e89aa4 00000014 00000004 017df358 rpcrt4!ObjectStublessClient+0x8b
017df338 77520369 000d6fcc 00000000 000fd74c rpcrt4!ObjectStubless+0xf
017df358 7752112b 000d6fcc 00000001 00000000 ole32!CProcessActivator::CCICallback+0x6d
017df378 775210e2 7760714c 000fd5a8 00000000 ole32!CProcessActivator::AttemptActivation+0x2c
017df3b0 77520453 7760714c 000fd5a8 00000000 ole32!CProcessActivator::ActivateByContext+0x42
017df3d8 77520143 7760714c 00000000 000fd74c ole32!CProcessActivator::CreateInstance+0x49
017df418 766858d4 000fd74c 00000000 000f4c88 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
017df484 77520143 000e8c50 00000000 000fd74c comsvcs!CSTAPoolActivator::CreateInstance+0x491
017df4c4 76675e13 000fd74c 00000000 000f4c88 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
017df510 77520143 000effe8 00000000 000fd74c comsvcs!CStdContextActivator::CreateInstance+0x1b2
017df550 7758dc24 000fd74c 00000000 000f4c88 ole32!ActivationPropertiesIn::DelegateCreateInstance+0xf7
017df57c 77e79dc9 0009d910 00000000 000fd74c ole32!CSurrogateProcessActivator::CreateInstance+0xc1
017df5a0 77ef321a 7758db63 017df5b4 00000004 rpcrt4!Invoke+0x30
017df9ac 77ef3bf3 000a86c8 000a2728 000f495c rpcrt4!NdrStubCall2+0x297
017dfa04 77600c31 000a86c8 000f495c 000a2728 rpcrt4!CStdStubBuffer_Invoke+0xc6
017dfa44 77600bdb 000f495c 000a85d0 00000000 ole32!SyncStubInvoke+0x33
017dfa8c 77522a22 000f495c 000a84a8 000a86c8 ole32!StubInvoke+0xa7
017dfb64 77522947 000a2728 00000000 000a86c8 ole32!CCtxComChnl::ContextInvoke+0xe3
017dfb80 77600b11 000f495c 00000001 000a86c8 ole32!MTAInvoke+0x1a
017dfbb0 776009bc 000f4908 000a2728 000a86c8 ole32!AppInvoke+0x9c
017dfc84 77600715 000f4908 000a29d8 000a85b8 ole32!ComInvokeWithLockAndIPID+0x2e0
017dfcd0 77e7988c 000f9f7c 000a85b8 000f9f7c ole32!ThreadInvoke+0x1cd
017dfd04 77e797f1 776005d0 000f9f7c 017dfdf0 rpcrt4!DispatchToStubInC+0x38
017dfd58 77e7971d 00000000 00000000 774ebfb8 rpcrt4!RPC_INTERFACE::DispatchToStubWorker+0x113
017dfd7c 77e8a067 000f9f7c 00000000 774ebfb8 rpcrt4!RPC_INTERFACE::DispatchToStub+0x84
017dfdbc 77e8a0a8 000f9f7c 000f9f38 00000000 rpcrt4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
017dfdfc 77e7bb6a 000fd4a0 000933b0 000ab8f8 rpcrt4!LRPC_SCALL::DealWithRequestMessage+0x2cd
017dfe20 77e76784 000933ec 017dfe38 000ab8f8 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0x16d
017dff80 77e76c22 017dffa8 77e76a3b 000933b0 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0x28f
017dff88 77e76a3b 000933b0 0175fbe0 00000403 rpcrt4!RecvLotsaCallsWrapper+0xd
017dffa8 77e76c0a 0009f760 017dffec 7c80b50b rpcrt4!BaseCachedThreadRoutine+0x79
017dffb4 7c80b50b 000f8b60 0175fbe0 00000403 rpcrt4!ThreadStartRoutine+0x1a
017dffec 00000000 77e76bf0 000f8b60 00000000 kernel32!BaseThreadStart+0x37

0:024> dc 000f4908
000f4908  774fd518 774fd7a8 00100004 00000001  ..Ow..Ow........
000f4918  00000204 00000000 00000000 00000001  ................
000f4928  00005c07 00001f9c ba0c42b1 8add039a  ........B......
000f4938  ffffffff 006d0065 774e1930 00070005  ....e.m.0.Nw....
000f4948  00000000 000f9ff0 00000000 000f9e58  ............X...
000f4958  00000000 000f4908 00000010 000fa018  .....I..........
000f4968  000013cc 00000004 000a85e4 000a85cc  ................
000f4978  000f9fa8 00000000 00000000 00009000  ................
0:024> dd
000f9e58
000f9e58  77e77cb8 89abcdef 00002000 00000002
000f9e68  00000000 00000000 00000000 00000000
000f9e78  00000000 00000000 00000000 00000000
000f9e88  00000000 00000000 000f9ff0 00000000
000f9e98  000f9ea4 00000004 00000000 00000000
000f9ea8  00000000 00000000 00000000 00000001
000f9eb8  00000000 00000000 00000000 00000000
000f9ec8  00000000 00000000 00000003 00000000
0:024> dd
000f9ed8  00000000 00000000 00000000 00000000
000f9ee8  00000001 00000000 000ab8f8 000fd4a0
000f9ef8  017dfe38 000b5118 00000001 00000000
000f9f08  000002d4 00001c08 01899923 00000000
000f9f18  00000000 00000000 00000000 00000000
000f9f28  00000342 00000001 00000000 00000000
000f9f38  00005c07 00001f9c ba0c42b1 8add039a
000f9f48  00000000 00000000 00000000 00000000


2d4는 Client의 ProcessID이고 1c08은 Client의 Thread ID가 됩니다.

덧글

댓글 입력 영역