windbg - 닷넷 Finalizer 스레드가 멈춰있는 현상
Finalizer 스레드가 멈춰있는 현상이 있습니다. 그 순간의 호출 스택에는 Managed 호출이 없었습니다.
0:015> !clrstack
OS Thread Id: 0xefc (15)
Child SP IP Call Site
000000abf226fc18 00007ffe59c9071a [DebuggerU2MCatchHandlerFrame: 000000abf226fc18]
따라서 사용자의 닷넷 코드에서 구현한 Finalizer에 문제가 있는 것은 아니라고 볼 수 있습니다. 게다가 Native 호출에도,
0:015> k
*** Stack trace for last set context - .thread/.cxr resets it
# Child-SP RetAddr Call Site
00 000000ab`f226e778 00007ffe`57111118 ntdll!NtWaitForSingleObject+0xa
01 000000ab`f226e780 00007ffe`5921f344 KERNELBASE!WaitForSingleObjectEx+0x94
02 000000ab`f226e820 00007ffe`590e0969 combase!MTAThreadWaitForCall+0x54 [d:\blue\com\combase\dcomrem\channelb.cxx @ 5657]
03 000000ab`f226e870 00007ffe`5921f145 combase!MTAThreadDispatchCrossApartmentCall+0x75 [d:\blue\com\combase\dcomrem\chancont.cxx @ 193]
04 (Inline Function) --------`-------- combase!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x322c [d:\blue\com\combase\dcomrem\channelb.cxx @ 5052]
05 000000ab`f226e8a0 00007ffe`5910bd27 combase!CRpcChannelBuffer::SendReceive2+0x64b [d:\blue\com\combase\dcomrem\channelb.cxx @ 4796]
06 (Inline Function) --------`-------- combase!ClientCallRetryContext::SendReceiveWithRetry+0x29 [d:\blue\com\combase\dcomrem\callctrl.cxx @ 1090]
07 (Inline Function) --------`-------- combase!CAptRpcChnl::SendReceiveInRetryContext+0x6a [d:\blue\com\combase\dcomrem\callctrl.cxx @ 715]
08 000000ab`f226eaf0 00007ffe`5910ba35 combase!DefaultSendReceive+0x87 [d:\blue\com\combase\dcomrem\callctrl.cxx @ 671]
09 000000ab`f226eb60 00007ffe`5910b991 combase!CAptRpcChnl::SendReceive+0x4d [d:\blue\com\combase\dcomrem\callctrl.cxx @ 753]
0a 000000ab`f226eb90 00007ffe`5921bd82 combase!CCtxComChnl::SendReceive+0x59f [d:\blue\com\combase\dcomrem\ctxchnl.cxx @ 735]
0b 000000ab`f226ed70 00007ffe`577f4679 combase!NdrExtpProxySendReceive+0x6e [d:\blue\com\combase\ndr\ndrole\proxy.cxx @ 2017]
0c 000000ab`f226eda0 00007ffe`5921b339 rpcrt4!NdrpClientCall3+0x467
0d 000000ab`f226f170 00007ffe`590a16f2 combase!ObjectStublessClient+0x149 [d:\blue\com\combase\ndr\ndrole\amd64\stblsclt.cxx @ 293]
0e 000000ab`f226f500 00007ffe`5910bf06 combase!ObjectStubless+0x42 [d:\blue\com\combase\ndr\ndrole\amd64\stubless.asm @ 174]
0f 000000ab`f226f550 00007ffe`59103fc8 combase!CObjectContext::InternalContextCallback+0x2af [d:\blue\com\combase\dcomrem\context.cxx @ 4428]
10 000000ab`f226f650 00007ffe`4f665694 combase!CObjectContext::ContextCallback+0x108 [d:\blue\com\combase\dcomrem\context.cxx @ 4330]
11 000000ab`f226f6f0 00007ffe`4f668d72 clr!CtxEntry::EnterContext+0x234
12 000000ab`f226f8c0 00007ffe`4f583508 clr!RCW::EnterContext+0x43
13 000000ab`f226f910 00007ffe`4f310d7c clr!RCWCleanupList::ReleaseRCWListInCorrectCtx+0x272784
14 000000ab`f226f940 00007ffe`4f32bce5 clr!RCWCleanupList::CleanupAllWrappers+0xf2
15 000000ab`f226f9b0 00007ffe`4f338cbe clr!SyncBlockCache::CleanupSyncBlocks+0xd1
16 000000ab`f226fa20 00007ffe`4f343c83 clr!Thread::DoExtraWorkForFinalizer+0x148
17 000000ab`f226fa50 00007ffe`4f330805 clr!SVR::GCHeap::FinalizerThreadWorker+0x78
18 000000ab`f226fa90 00007ffe`4f33078c clr!ManagedThreadBase_DispatchInner+0x2d
19 000000ab`f226fad0 00007ffe`4f3306f5 clr!ManagedThreadBase_DispatchMiddle+0x6c
1a 000000ab`f226fbd0 00007ffe`4f2f1cb7 clr!ManagedThreadBase_DispatchOuter+0x75
1b 000000ab`f226fc60 00007ffe`4f32e8b6 clr!SVR::GCHeap::FinalizerThreadStart+0xd7
1c 000000ab`f226fd00 00007ffe`574d13d2 clr!Thread::intermediateThreadProc+0x7d
1d 000000ab`f226fdc0 00007ffe`59c154f4 kernel32!BaseThreadInitThunk+0x22
1e 000000ab`f226fdf0 00000000`00000000 ntdll!RtlUserThreadStart+0x34
전혀 사용자의 코드가 관여하고 있지 않습니다. 심각하군요. ^^;
그래도 native 호출 스택에서 건질만한 것이 좀 있습니다.
...[생략]...
03 000000ab`f226e870 00007ffe`5921f145 combase!MTAThreadDispatchCrossApartmentCall+0x75 [d:\blue\com\combase\dcomrem\chancont.cxx @ 193]
...[생략]...
12 000000ab`f226f8c0 00007ffe`4f583508 clr!RCW::EnterContext+0x43
13 000000ab`f226f910 00007ffe`4f310d7c clr!RCWCleanupList::ReleaseRCWListInCorrectCtx+0x272784
...[생략]...
즉, Finalizer 스레드가 응용 프로그램에서 사용한 RCW(Runtime Callable Wrapper) 객체를 해지하다가 COM Apartment 경계를 넘어 호출하는 과정에서 hang이 발생한 것입니다.
Finalizer 스레드는 기본적으로 MTA 유형이기 때문에 MTA COM 객체에 대해서는 저런 식으로 Apartment 경계를 넘는 호출은 발생하지 않습니다. 따라서 STA COM 객체를 생성한 후 정상적으로 해제하지 않은 상태에서 Finalizer 스레드가 그 COM 객체의 RCW 종료자를 호출하는 과정에서 저런 문제가 발생한 것입니다.
실제로 그런지 테스트를 해볼까요? ^^
별도의 COM 바이너리를 만들 필요 없이 간단하게 레지스트리에 현재 존재하는 STA COM 객체를 하나 골라보겠습니다.
{0B124F8F-91F0-11D1-B8B5-006008059382}
Installed Apps Enumerator
Threading Model - Apartment
C#에서는 해당 객체를 다음과 같이 STA에서 활성화할 수 있습니다.
using System;
using System.Threading;
namespace ConsoleApp1
{
class Program
{
static void Main(string[] args)
{
Thread t = new Thread(threadFunc);
t.ApartmentState = ApartmentState.STA;
t.Start();
t.Join();
}
private static void threadFunc()
{
CallTest();
Console.WriteLine("Press any key to signal to GC");
Console.ReadLine();
GC.Collect(2, GCCollectionMode.Forced);
Console.WriteLine("Sent signal to GC, press any key to exit...");
Console.ReadLine();
}
private static void CallTest()
{
string guid = "{0B124F8F-91F0-11D1-B8B5-006008059382}"; // STA
dynamic host = InteropExtension.CoCreateInstance(guid);
}
}
public class InteropExtension
{
public static object CoCreateInstance(string guid)
{
Guid coClassGuid = new Guid(guid);
System.Type type = System.Type.GetTypeFromCLSID(coClassGuid);
return Activator.CreateInstance(type);
}
}
}
위의 프로그램을 실행 후, windbg로 "Attach to process"를 이용해 디버거 연결을 하고 다음과 같이 BP를 걸어둡니다.
0:010> bp combase!MTAThreadDispatchCrossApartmentCall
0:010> g
이제 (Console.ReadLine을 벗어나기 위해) Enter 키를 치면 windbg가 다음의 메시지와 함께 디버깅 모드로 진입하게 됩니다.
Breakpoint 0 hit
combase!MTAThreadDispatchCrossApartmentCall:
00007ffa`ea993320 4c8bdc mov r11,rsp
다음 단계의 호출 함수에 BP를 걸어야 하는데요, 제 컴퓨터에서 실습할 때 combase!MTAThreadWaitForCall의 bp는 잡히지 않았습니다. (이유는 나중에 나옵니다.) 또한, "bp ntdll!NtWaitForSingleObject"로 하면 Console.ReadLine 쪽 코드에서 BP가 걸릴 뿐입니다. 왜냐하면 제 환경에서는 NtWaitForSingleObject가 아닌 "NtWaitForMultipleObjects"를 호출하므로 다음과 같이 BP 설정이 필요했습니다.
0:010> bp ntdll!NtWaitForMultipleObjects
이후 다시 'g' 키를 눌러 진행하면 다음과 같이 callstack이 보입니다.
0:005> k
# Child-SP RetAddr Call Site
00 00000000`1b28e188 00007ffa`ea28c01e ntdll!NtWaitForMultipleObjects
01 00000000`1b28e190 00007ffa`ea99349e KERNELBASE!WaitForMultipleObjectsEx+0xfe
02 (Inline Function) --------`-------- combase!MTAThreadWaitForCall+0xbd [onecore\com\combase\dcomrem\channelb.cxx @ 7429]
03 00000000`1b28e490 00007ffa`ea9554ac combase!MTAThreadDispatchCrossApartmentCall+0x17e [onecore\com\combase\dcomrem\chancont.cxx @ 235]
04 (Inline Function) --------`-------- combase!CSyncClientCall::SwitchAptAndDispatchCall+0x34a [onecore\com\combase\dcomrem\channelb.cxx @ 6026]
05 00000000`1b28e520 00007ffa`ea9c2c45 combase!CSyncClientCall::SendReceive2+0x42c [onecore\com\combase\dcomrem\channelb.cxx @ 5722]
06 (Inline Function) --------`-------- combase!SyncClientCallRetryContext::SendReceiveWithRetry+0x25 [onecore\com\combase\dcomrem\callctrl.cxx @ 1641]
07 (Inline Function) --------`-------- combase!CSyncClientCall::SendReceiveInRetryContext+0x25 [onecore\com\combase\dcomrem\callctrl.cxx @ 571]
08 00000000`1b28e710 00007ffa`ea954899 combase!DefaultSendReceive+0x65 [onecore\com\combase\dcomrem\callctrl.cxx @ 529]
09 00000000`1b28e770 00007ffa`ea992c24 combase!CSyncClientCall::SendReceive+0x2f9 [onecore\com\combase\dcomrem\ctxchnl.cxx @ 765]
0a 00000000`1b28e9a0 00007ffa`ea9c7cce combase!CClientChannel::SendReceive+0x84 [onecore\com\combase\dcomrem\ctxchnl.cxx @ 696]
0b 00000000`1b28ea10 00007ffa`ead2a009 combase!NdrExtpProxySendReceive+0x4e [onecore\com\combase\ndr\ndrole\proxy.cxx @ 1965]
0c 00000000`1b28ea40 00007ffa`ea9c64fb RPCRT4!NdrpClientCall3+0x8e9
0d 00000000`1b28edf0 00007ffa`eaa3c922 combase!ObjectStublessClient+0x13b [onecore\com\combase\ndr\ndrole\amd64\stblsclt.cxx @ 369]
0e 00000000`1b28f180 00007ffa`ea983102 combase!ObjectStubless+0x42 [onecore\com\combase\ndr\ndrole\amd64\stubless.asm @ 176]
0f 00000000`1b28f1d0 00007ffa`ea9e658f combase!CObjectContext::InternalContextCallback+0x252 [onecore\com\combase\dcomrem\context.cxx @ 4407]
10 00000000`1b28f2f0 00007ffa`d4b3e137 combase!CObjectContext::ContextCallback+0x7f [onecore\com\combase\dcomrem\context.cxx @ 4304]
11 00000000`1b28f390 00007ffa`d4b41df6 clr!CtxEntry::EnterContext+0x287
12 00000000`1b28f570 00007ffa`d4b44027 clr!RCW::EnterContext+0x43
13 00000000`1b28f5c0 00007ffa`d4a3fb80 clr!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xd5
14 00000000`1b28f5f0 00007ffa`d47fed7c clr!RCWCleanupList::CleanupAllWrappers+0x240dfc
15 00000000`1b28f650 00007ffa`d47ff71e clr!SyncBlockCache::CleanupSyncBlocks+0xcf
16 00000000`1b28f6c0 00007ffa`d47ff381 clr!Thread::DoExtraWorkForFinalizer+0x200
17 00000000`1b28f750 00007ffa`d4667d01 clr!FinalizerThread::FinalizerThreadWorker+0x91
18 00000000`1b28f790 00007ffa`d4667c70 clr!ManagedThreadBase_DispatchInner+0x39
19 00000000`1b28f7d0 00007ffa`d4667bad clr!ManagedThreadBase_DispatchMiddle+0x6c
1a 00000000`1b28f8d0 00007ffa`d46f785a clr!ManagedThreadBase_DispatchOuter+0x75
1b 00000000`1b28f960 00007ffa`d4715abf clr!FinalizerThread::FinalizerThreadStart+0x126
1c 00000000`1b28fa00 00007ffa`eb147e94 clr!Thread::intermediateThreadProc+0x86
1d 00000000`1b28fac0 00007ffa`ed5ea251 KERNEL32!BaseThreadInitThunk+0x14
1e 00000000`1b28faf0 00000000`00000000 ntdll!RtlUserThreadStart+0x21
이것으로 일단 호출 스택은 재현을 했습니다. (위의 결과에 보면, "bp combase!MTAThreadWaitForCall"은 BP가 걸리지 않은 이유가 "(Inline Function)"이기 때문으로 보입니다.)
자, 그럼 이제부터 변형을 해보겠습니다. STA COM 객체를 STA가 아니라 MTA에서 생성하도록 기존 코드에서 다음의 한 줄만 바꿉니다.
static void Main(string[] args)
{
Thread t = new Thread(threadFunc);
t.ApartmentState = ApartmentState.MTA;
t.Start();
t.Join();
}
당연하지만, STA COM 객체는 MTA에서 생성한 경우 COM+ 인프라는 새롭게 STA를 생성한 후 그 문맥에 STA를 생성한 후 마샬링을 합니다. 따라서, 위의 코드 변경은 기존 2개의 BP 테스트에 대해,
bp combase!MTAThreadDispatchCrossApartmentCall
bp ntdll!NtWaitForMultipleObjects
동일한 결과를 갖습니다.
그렇다면, MTA COM 객체를 생성하면 어떻게 될까요? 이를 위해 COM GUID 값을 다음과 같이 바꿔줍니다.
private static void CallTest()
{
string guid = "{CB2F6723-AB3A-11D2-9C40-00C04FA30A3E}"; // Both
dynamic host = InteropExtension.CoCreateInstance(guid);
}
이후 실행하면, 이제 "combase!MTAThreadDispatchCrossApartmentCall" 함수에서 BP가 걸리지 않습니다. 대신 RCW를 해제하는 레벨로 내려가,
bp clr!RCWCleanupList::ReleaseRCWListInCorrectCtx
테스트하면 이제는 BP가 걸립니다. 확인이 재미있군요. ^^
이 테스트를 통해, 사용자가 별도 조치를 취하지 않은 COM 객체는 GC 과정에서 Finalizer에 의해 정리된다는 것을 알게 되었습니다. 그렇다면 Finalizer의 부담을 더는 것도 가능하지 않을까요?
이를 위해 다시 처음의 STA COM 객체를 생성하도록 코드를 변경한 후 명시적인 해제 코드를 추가해 봅니다.
private static void CallTest()
{
string guid = "{0B124F8F-91F0-11D1-B8B5-006008059382}"; // STA
dynamic host = InteropExtension.CoCreateInstance(guid);
Marshal.ReleaseComObject(host);
}
위와 같이 처리해 주면 STA 객체임에도 이제 더 이상 Finalizer 스레드에서 combase!MTAThreadDispatchCrossApartmentCall 호출이 발생하지 않습니다.
정리해 보면, 그러니까 해당 웹 애플리케이션에서 어디선가 STA COM 객체를 생성했고 그것을 해제하는 과정에서 hang이 발생한 것입니다. 이것이 그 COM 객체의 특수성 때문인지... 다른 환경적인 문제가 있는 것인지는 덤프 파일만 받은 외부에서는 더 이상 알 길이 없습니다. ^^
그러고 보니, 전에도 Finalizer 관련해서 쓴 글이 있군요. ^^
windbg 분석 사례 - 종료자(Finalizer)에서 예외가 발생한 경우 비정상 종료(Crash) 발생
; https://www.sysnet.pe.kr/2/0/11732
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]