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

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:techsharer@outlook.com

비밀번호

댓글 쓴 사람
 




1  2  3  4  5  6  7  [8]  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
11833정성태5/14/2019507개발 환경 구성: 431. Visual Studio 2019 - CMake를 이용한 공유/실행(so/out) 리눅스 프로젝트 설정파일 다운로드1
11832정성태3/4/2019496오류 유형: 524. Visual Studio CMake - rsync: connection unexpectedly closed
11831정성태3/4/2019394오류 유형: 523. Visual Studio 2019 - 새 창으로 뜬 윈도우를 닫을 때 비정상 종료
11830정성태2/26/2019405오류 유형: 522. 이벤트 로그 - Error opening event log file State. Log will not be processed. Return code from OpenEventLog is 87.
11829정성태2/26/2019530개발 환경 구성: 430. 마이크로소프트의 CoreCLR 프로파일러 예제 빌드 방법 - 리눅스 환경 [1]
11828정성태2/26/2019735개발 환경 구성: 429. Component Services 관리자의 RuntimeBroker 설정이 2개 있는 경우
11827정성태2/26/2019573오류 유형: 521. Visual Studio - Could not start the 'rsync' command on the remote host, please install it using your system package manager.
11826정성태2/26/2019477오류 유형: 520. 우분투에 .NET Core SDK 설치 시 패키지 의존성 오류
11825정성태2/25/2019980개발 환경 구성: 428. Visual Studio 2019 - CMake를 이용한 리눅스 빌드 환경 설정
11824정성태2/25/2019726오류 유형: 519. The SNMP Service encountered an error while accessing the registry key SYSTEM\CurrentControlSet\Services\SNMP\Parameters\TrapConfiguration. [1]
11823정성태2/21/2019433오류 유형: 518. IIS 관리 콘솔이 뜨지 않는 문제
11822정성태2/20/2019522오류 유형: 517. docker에 설치한 MongoDB 서버로 연결이 안 되는 경우
11821정성태2/20/2019521오류 유형: 516. Visual Studio 2019 - This extension uses deprecated APIs and is at risk of not functioning in a future VS update. [1]
11820정성태2/20/20191491오류 유형: 515. 윈도우 10 1809 업데이트 후 "User Profiles Service" 1534 경고 발생
11819정성태2/20/2019557Windows: 158. 컴퓨터와 사용자의 SID(security identifier) 확인 방법
11818정성태2/20/2019771VS.NET IDE: 131. Visual Studio 2019 Preview의 닷넷 프로젝트 빌드가 20초 이상 걸리는 경우 [2]
11817정성태2/17/2019693오류 유형: 514. WinDbg Preview 실행 오류 - Error : DbgX.dll : WindowsDebugger.WindowsDebuggerException: Could not load dbgeng.dll
11816정성태2/17/2019558Windows: 157. 윈도우 스토어 앱(Microsoft Store App)을 명령행에서 직접 실행하는 방법
11815정성태2/14/2019804오류 유형: 513. Visual Studio 2019 - VSIX 설치 시 "The extension cannot be installed to this product due to prerequisites that cannot be resolved." 오류 발생
11814정성태2/12/2019516오류 유형: 512. VM(가상 머신)의 NT 서비스들이 자동 시작되지 않는 문제
11813정성태2/12/2019573.NET Framework: 809. C# - ("Save File Dialog" 등의) 대화 창에 확장 속성을 보이는 방법
11812정성태2/11/2019481오류 유형: 511. Windows Server 2003 VM 부팅 후 로그인 시점에 0xC0000005 BSOD 발생
11811정성태2/11/2019616오류 유형: 510. 서버 운영체제에 NVIDIA GeForce Experience 실행 시 wlanapi.dll 누락 문제
11810정성태2/11/2019461.NET Framework: 808. .NET Profiler - GAC 모듈에서 GAC 비-등록 모듈을 참조하는 경우의 문제
11809정성태2/11/2019603.NET Framework: 807. ClrMD를 이용해 메모리 덤프 파일로부터 특정 인스턴스를 참조하고 있는 소유자 확인
11808정성태2/8/20191013디버깅 기술: 123. windbg - 닷넷 응용 프로그램의 메모리 누수 분석
1  2  3  4  5  6  7  [8]  9  10  11  12  13  14  15  ...