Microsoft MVP성태의 닷넷 이야기
디버깅 기술: 121. windbg - 닷넷 Finalizer 스레드가 멈춰있는 현상 [링크 복사], [링크+제목 복사]
조회: 551
글쓴 사람
정성태 (kevin13@chol.net)
홈페이지
첨부 파일
 

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




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]





[최초 등록일: ]
[최종 수정일: 1/10/2019 ]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:kevin13@chol.com

비밀번호

댓글 쓴 사람
 




[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
11872정성태4/17/201958.NET Framework: 819. (번역글) .NET Internals Cookbook Part 4 - Type members파일 다운로드1
11871정성태4/16/201995.NET Framework: 818. (번역글) .NET Internals Cookbook Part 3 - Initialization tricks [3]파일 다운로드1
11870정성태4/16/201946.NET Framework: 817. Process.Start로 실행한 콘솔 프로그램의 출력 결과를 얻는 방법파일 다운로드1
11869정성태4/15/201998.NET Framework: 816. (번역글) .NET Internals Cookbook Part 2 - GC-related things파일 다운로드1
11868정성태4/15/201969.NET Framework: 815. CER(Constrained Execution Region)이란?파일 다운로드1
11867정성태4/15/201962.NET Framework: 814. Critical Finalizer와 SafeHandle의 사용 의미파일 다운로드1
11866정성태4/9/2019106Windows: 159. 네트워크 공유 폴더(net use)에 대한 인증 정보는 언제까지 유효할까요?
11865정성태4/9/201937오류 유형: 529. 제어판 - C:\ProgramData\Microsoft\Windows\Start Menu\Programs\Administrative Tools is not accessible.
11864정성태4/9/201936오류 유형: 528. '...' could be '0': this does not adhere to the specification for the function '...'
11863정성태4/9/201968디버깅 기술: 127. windbg - .NET x64 EXE의 EntryPoint
11862정성태4/7/2019103개발 환경 구성: 437. .NET EXE의 ASLR 기능을 끄는 방법
11861정성태4/6/201987디버깅 기술: 126. windbg - .NET x86 CLR2/CLR4 EXE의 EntryPoint
11860정성태4/5/201983오류 유형: 527. Visual C++ 컴파일 오류 - error C2220: warning treated as error - no 'object' file generated
11859정성태4/4/201983디버깅 기술: 125. WinDbg로 EXE의 EntryPoint에서 BP 거는 방법
11858정성태3/27/2019138VC++: 129. EXE를 LoadLibrary로 로딩해 PE 헤더에 있는 EntryPoint를 직접 호출하는 방법파일 다운로드1
11857정성태3/26/2019161VC++: 128. strncpy 사용 시 주의 사항(Linux / Windows)
11856정성태3/25/201994VS.NET IDE: 134. 마이크로소프트의 CoreCLR 프로파일러 리눅스 예제를 Visual Studio F5 원격 디버깅하는 방법파일 다운로드1
11855정성태3/25/201988개발 환경 구성: 436. 페이스북 HTTPS 인증을 localhost에서 테스트하는 방법
11854정성태3/25/2019111VS.NET IDE: 133. IIS Express로 호스팅하는 사이트를 https로 접근하는 방법
11853정성태3/24/2019183개발 환경 구성: 435. 존재하지 않는 IP 주소에 대한 Dns.GetHostByAddress/gethostbyaddr/GetNameInfoW 실행이 느리다면? - 두 번째 이야기
11852정성태3/20/2019184개발 환경 구성: 434. 존재하지 않는 IP 주소에 대한 Dns.GetHostByAddress/gethostbyaddr/GetNameInfoW 실행이 느리다면?파일 다운로드1
11851정성태3/19/2019180Linux: 8. C# - 리눅스 환경에서 DllImport 대신 라이브러리 동적 로드 처리
11850정성태3/18/2019234.NET Framework: 813. C# async 메서드에서 out/ref/in 유형의 인자를 사용하지 못하는 이유
11849정성태3/18/2019172.NET Framework: 812. pscp.exe 기능을 C#으로 제어하는 방법파일 다운로드1
11848정성태3/17/2019156스크립트: 14. 윈도우 CMD - 파일이 변경된 경우 파일명을 변경해 복사하고 싶다면?
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...