Microsoft MVP성태의 닷넷 이야기
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일

C# - Thread.Suspend 호출 시 응용 프로그램 hang 현상 (2)

지난 글에서,

C# - Thread.Suspend 호출 시 응용 프로그램 hang 현상
; https://www.sysnet.pe.kr/2/0/11473

마지막에 ETW 이벤트를 실시간으로 잡을 수 있다면 deadlock 현상을 피할 수 있을 것처럼 설명했는데요. 가만 보니, CRL Profiler 측의 콜백 이벤트가 gc가 아닌 COR_PRF_MONITOR_SUSPENDS 유에 속하는 것이라서,

COR_PRF_MONITOR Enumeration
; https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/profiling/cor-prf-monitor-enumeration

COR_PRF_MONITOR_SUSPENDS - Controls the RuntimeSuspend*, RuntimeResume*, RuntimeThreadSuspended, and RuntimeThreadResumed callbacks in the ICorProfilerCallback interface.


시스템 부하 없이 가능할 것 같아 테스트를 해봤습니다. 이름이 유추하는 것에 따라, 각각의 ETW 이벤트는 ICorProfilerCallback 콜백에 대해 다음과 같이 대응을 하는데요,

GCSuspendEE_V1      ==> RuntimeSuspendStarted
GCSuspendEEEnd_V1   ==> RuntimeSuspendFinished
GCStart_V1          ==> (COR_PRF_MONITOR_GC 범주의) GarbageCollectionStarted
GCEnd_V1            ==> (COR_PRF_MONITOR_GC 범주의) GarbageCollectionFinished
GCRestartEEBegin_V1 ==> RuntimeResumeStarted
GCRestartEEEnd_V1   ==> RuntimeResumeFinished

자, 그럼 기본으로 만들어 둔 CLR Profiler 예제 코드에 아래의 추가 코드를 넣고,

static int s_suspend = 0;
static int s_resumed = 0;
volatile static unsigned long s_intLock = 0;

__declspec(dllexport) bool __stdcall IsRunningGC()
{
    return s_intLock == 1;
}

HRESULT CBasicClrProfiler::RuntimeSuspendStarted(COR_PRF_SUSPEND_REASON suspendReason)
{
    s_suspend++;
    s_intLock = 1;

    return S_OK;
}


HRESULT CBasicClrProfiler::RuntimeResumeFinished()
{
    s_intLock = 0;
    s_resumed++;

    return S_OK;
}

재현 코드의 GetCallStack 메서드는 IsRunningGC == false인 상태에서만 호출하게 변경합니다.

[DllImport("SampleProfiler.dll")]
[return: MarshalAs(UnmanagedType.Bool)]
public static extern bool IsRunningGC();

private static string GetCallStack(Thread t)
{
    System.Diagnostics.StackTrace trace = null;
    bool suspended = false;

    try
    {
        if (IsRunningGC() == false)
        {
            t.Suspend();
            suspended = true;

            trace = new System.Diagnostics.StackTrace(t, false);
            return trace.ToString();
        }
    }
    catch { }
    finally
    {
        if (suspended == true)
        {
            t.Resume();
        }
    }

    return "";
}

그런데, 실제로 실행해 보면 이번에도 데드락이 걸리는 것은 마찬가지입니다. 그 상태의 덤프를 떠서 windbg로 분석해 보면,

.loadby sos clr

0:000>  !threads
ThreadCount:      7
UnstartedThread:  0
BackgroundThread: 6
PendingThread:    0
DeadThread:       0
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1 609c 000001751bcd0850    2a020 Preemptive  000001751D8F5D28:000001751D8F5FB0 000001751bc96960 0     MTA 
   6    2 85b8 000001751bcf96b0    2b220 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     MTA (Finalizer) 
   7    3 a8a8 000001751bd29ae0    2b220 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     MTA 
   8    4 183c 000001751bd2d0f0    ab224 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     MTA 
   9    5 9ddc 000001751bd2f650    2b220 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     MTA 
  10    6 b970 000001751bd3c0f0    2b220 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     MTA 
  11    7 7c5c 000001751bd433c0    21220 Preemptive  0000000000000000:0000000000000000 000001751bc96960 0     Ukn 

지난번 덤프 분석과 마찬가지로 스레드 호출 스택의 대상이 되는 스레드는 trigger_gc_for_alloc을 호출하며 중지해 있고,

0:008> !ThreadState ab224
    User Suspend Pending
    Legal to Join
    Background
    CLR Owns
    CoInitialized
    In Multi Threaded Apartment
    Fully initialized
    Sync Suspended

0:008> k
 # Child-SP          RetAddr               Call Site
...[생략]...

08 0000004e`50cfe7e0 00007ff8`6dd6e69f     clr!GCToEEInterface::EnablePreemptiveGC+0x3d
09 0000004e`50cfe810 00007ff8`6e2b992b     clr!WKS::GCHeap::GarbageCollectGeneration+0x97
0a 0000004e`50cfe860 00007ff8`6e0cd99c     clr!WKS::gc_heap::trigger_gc_for_alloc+0x37
0b 0000004e`50cfe8a0 00007ff8`6de549fa     clr!WKS::gc_heap::try_allocate_more_space+0x278f80
0c 0000004e`50cfe900 00007ff8`6de5498b     clr!WKS::gc_heap::allocate_more_space+0x26
...[생략]...

GetCallStack 메서드를 호출 중인 0번 스레드는 wait_for_gc_done 호출 상태라 멈춰 있습니다.

0:000> k
 # Child-SP          RetAddr               Call Site
...[생략]...
04 0000004e`504fea40 00007ff8`6dd71732     clr!CLREventBase::WaitEx+0x71
05 0000004e`504fead0 00007ff8`6dd742f6     clr!WKS::gc_heap::wait_for_gc_done+0x2b
06 0000004e`504feb00 00007ff8`6dd50848     clr!WKS::GCHeap::Alloc+0x276
...[생략]...

그리고 이때의 C++ profiler 측 전역 변수를 살펴보면,

0:000> x SampleProfiler!s_suspend
00007ff8`6b3944bc SampleProfiler!s_suspend = 0n333

0:000> x SampleProfiler!s_resumed
00007ff8`6b3944c0 SampleProfiler!s_resumed = 0n333

0:000> x SampleProfiler!s_intLock
00007ff8`6b3944b4 SampleProfiler!s_intLock = 0

현재 trigger_gc_for_alloc 호출로 인해 런타임이 suspend 되었을 것임에도 불구하고 ICorProfilerCallback의 RuntimeSuspendStarted, RuntimeResumeFinished 이벤트는 쌍을 이뤄 이미 호출이 완료된 상태입니다. 이러한 결과에 대한 해석을 제대로 하려면 CLR 측 소스 코드를 면밀히 분석해야 하는데... 제 실력이 아직 거기까지는 안 되는군요. (혹시 이에 대해 아시는 분은 덧글 부탁드립니다. ^^)




그런데, 사실 저 동작이 정확하게 지켜졌다고 해도, IsRunningGC() 호출 결과 false일 때만 호출 스택을 구하는 것 역시 불안정하긴 마찬가지입니다. 왜냐하면, IsRunningGC 호출로 false을 얻은 바로 그 순간 GC가 발생한다면 마찬가지로 데드락에 빠질 수 있는 위험이 있기 때문입니다.

그러니까, 결국 GetCallStack 메서드의 호출과 GC는 최대한 엮이지 않는 것이 최선입니다. 이와 관련해서 생각나는 글이 있는데,

C# - Thread.Suspend 호출 시 응용 프로그램 hang 현상을 해결하기 위한 시도
; https://www.sysnet.pe.kr/2/0/12028

위에서는 GC가 임박한 경우 GetCallStack을 호출하지 않도록 변경했었는데요, 그러지 말고 GetCallStack 메서드를 호출하는 동안에는 GC가 발생하지 않도록 만드는 것은 어떨까요? 마침 .NET 4.6부터 이에 대한 기능이 추가되었습니다.

GC.TryStartNoGCRegion Method
; https://docs.microsoft.com/en-us/dotnet/api/system.gc.trystartnogcregion

GC.EndNoGCRegion Method
; https://docs.microsoft.com/en-us/dotnet/api/system.gc.endnogcregion

따라서 GetCallStack을 다음과 같이 만들어 두면,

private static string GetCallStack(Thread t)
{
    System.Diagnostics.StackTrace trace = null;
    bool suspended = false;

    try
    {
        if (GC.TryStartNoGCRegion(1024 * 1024 * 10) == true)
        {
            t.Suspend();
            suspended = true;

            trace = new System.Diagnostics.StackTrace(t, false);
            return trace.ToString();
        }
    }
    catch { }
    finally
    {
        if (GCSettings.LatencyMode == GCLatencyMode.NoGCRegion)
        {
            GC.EndNoGCRegion();
        }

        if (suspended == true)
        {
            t.Resume();
        }
    }

    return "";
}

TryStartNoGCRegion 호출 시점에 미리 10MB의 힙 공간을 확보해 두고 new System.Diagnostics.StackTrace(t, false).ToString()을 호출하게 되므로 이 과정에서 GC가 발생하지 않게 됩니다. 따라서 위의 예제를 실행하면 이전과 달리 데드락 문제가 발생하지 않습니다.

위의 코드에서 한 가지 애매한 점이 있다면, 호출 스택을 구하기 위해 미리 확보하는 10MB의 크기입니다. 사실 호출 스택은 그 깊이에 따라 천차만별일 수 있기 때문에 정확한 값을 지정할 수 없습니다. 그저 적당한 값을 넣어야 하는데 글쎄요... 10MB면 될까요? 알 수 없습니다. 참고로, 이 크기는 Ephemeral generation의 최대 세그먼트까지 지정할 수 있는데,

Ephemeral generations and segments
; https://docs.microsoft.com/en-us/dotnet/standard/garbage-collection/fundamentals?#ephemeral-generations-and-segments

위의 문서에 명시하듯이 32비트는 16MB, 64비트는 256MB로 가정하면 모든 환경에서 사용할 수 있습니다.

Workstation GC: 32비트 - 16MB, 64비트 - 256MB
Server GC: 32비트 - 64MB, 64비트 - 4GB
Server GC with > 4 logical CPUs: 32비트 - 32MB, 64비트 - 2GB
Server GC with > 8 logical CPUs: 32비트 - 16MB, 64비트 - 1GB

(첨부 파일은 이 글의 예제 코드를 포함합니다.)




이걸로 해결이 된 듯싶지만, 실제로 상용 코드에 저 방법을 적용할 수는 없었습니다. 저 간단한 예제는 통과를 했지만, 제가 가지고 있는 ASP.NET 웹 애플리케이션 테스트 사이트에 저 코드를 넣었더니 특정 테스트 머신에서 불특정하게 crash가 발생했으며 이때의 덤프를 보면 다음과 같은 faulting 오류가 보입니다.

CLR!SVR::GC_HEAP::FIND_FIRST_OBJECT+83In ....dmp the assembly instruction at clr!SVR::gc_heap::find_first_object+83 in C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll from Microsoft Corporation has caused an access violation exception (0xC0000005) when trying to read from memory location 0x00000000 on thread 18


0:018> k
 # Child-SP          RetAddr               Call Site
00 000000c6`30c7d678 00007fff`a337bf56     clr!SVR::gc_heap::find_first_object+0x83
01 000000c6`30c7d690 00007fff`a32c9c50     clr!SVR::GCHeap::Promote+0x147
02 000000c6`30c7d710 00007fff`a32c9d8a     clr!GcEnumObject+0x218
03 000000c6`30c7d760 00007fff`a32c8587     clr!GcInfoDecoder::EnumerateLiveSlots+0xdf3
04 000000c6`30c7dbe0 00007fff`a32c819e     clr!GcStackCrawlCallBack+0x307
05 000000c6`30c7e000 00007fff`a33748de     clr!GCToEEInterface::GcScanRoots+0x469
06 000000c6`30c7f4c0 00007fff`a3373a47     clr!SVR::gc_heap::mark_phase+0x1de
07 000000c6`30c7f560 00007fff`a3373cb6     clr!SVR::gc_heap::gc1+0xa7
08 000000c6`30c7f5b0 00007fff`a3373448     clr!SVR::gc_heap::garbage_collect+0x870
09 000000c6`30c7f650 00007fff`a3316107     clr!SVR::gc_heap::gc_thread_function+0x74
0a 000000c6`30c7f680 00007fff`a3317e14     clr!SVR::gc_heap::gc_thread_stub+0x7e
0b 000000c6`30c7f9c0 00007fff`b13b7974     clr!GCThreadStub+0x24
0c 000000c6`30c7f9f0 00007fff`b169a2d1     kernel32!BaseThreadInitThunk+0x14
0d 000000c6`30c7fa20 00000000`00000000     ntdll!RtlUserThreadStart+0x21

로그 이름:         Application
원본:            .NET Runtime
...[생략]...
설명:
Application: w3wp.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an internal error in the .NET Runtime at IP 00007FF89FE91036 (00007FF89FDE0000) with exit code 80131506.

프로세스 crash이기 때문에 별도 로그를 남겨본 결과 GC.TryStartNoGCRegion 메서드까지 호출은 했으나, 그 이후에 남은 로그가 없는 걸로 봐서는 이로 인해 GC가 발생했고, (ASP.NET의 ServerGC 유형으로) 그것을 처리하는 GC 전용 스레드에서 find_first_object 호출 시 crash로 이어지는 듯합니다. 물론, 테스트를 위한 응용 프로그램이어서 약간 복잡하긴 했지만... 그래도 저 오류가 발생하는 것은 심각할 수밖에 없습니다.




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

[연관 글]


donaricano-btn



[최초 등록일: ]
[최종 수정일: 5/14/2021

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

비밀번호

댓글 쓴 사람
 




1  2  3  4  5  6  7  8  9  10  [11]  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
12485정성태1/11/20211087Graphics: 38. C# - OpenCvSharp.VideoWriter에 BMP 파일을 1초씩 출력하는 예제파일 다운로드1
12484정성태1/9/2021994.NET Framework: 1002. C# - ReadOnlySequence<T> 소개파일 다운로드1
12483정성태1/8/2021895개발 환경 구성: 521. dotPeek - 훌륭한 역어셈블 소스 코드 생성 도구
12482정성태1/8/2021776.NET Framework: 1001. C# - 제네릭 타입/메서드에서 사용 시 경우에 따라 CS8377 컴파일 에러
12481정성태1/7/2021737.NET Framework: 1000. C# - CS8344 컴파일 에러: ref struct 타입의 사용 제한 메서드파일 다운로드1
12480정성태1/6/20211183.NET Framework: 999. C# - ArrayPool<T>와 MemoryPool<T> 소개파일 다운로드1
12479정성태1/6/2021813.NET Framework: 998. C# - OWIN 예제 프로젝트 만들기
12478정성태1/5/2021982.NET Framework: 997. C# - ArrayPool<T> 소개파일 다운로드1
12477정성태1/5/20211728기타: 79. github 코드 검색 방법 [1]
12476정성태1/5/20211034.NET Framework: 996. C# - 닷넷 코어에서 다른 스레드의 callstack을 구하는 방법파일 다운로드1
12475정성태1/5/20211050.NET Framework: 995. C# - Span<T>와 Memory<T> [1]파일 다운로드1
12474정성태1/4/2021890.NET Framework: 994. C# - (.NET Core 2.2부터 가능한) 프로세스 내부에서 CLR ETW 이벤트 수신파일 다운로드1
12473정성태1/4/20211001.NET Framework: 993. .NET 런타임에 따라 달라지는 정적 필드의 초기화 유무 [1]파일 다운로드1
12472정성태1/3/2021925디버깅 기술: 178. windbg - 디버그 시작 시 스크립트 실행
12471정성태1/1/20211029.NET Framework: 992. C# - .NET Core 3.0 이상부터 제공하는 runtimeOptions의 rollForward 옵션
12470정성태12/30/20201096.NET Framework: 991. .NET 5 응용 프로그램에서 WinRT API 호출 [1]파일 다운로드1
12469정성태12/30/20201261.NET Framework: 990. C# - SendInput Win32 API를 이용한 가상 키보드/마우스파일 다운로드1
12468정성태12/30/2020858Windows: 186. CMD Shell의 "Defaults"와 "Properties"에서 폰트 정보가 다른 문제
12467정성태12/29/20201045.NET Framework: 989. HttpContextAccessor를 통해 이해하는 AsyncLocal<T> [1]파일 다운로드1
12466정성태12/29/20201213.NET Framework: 988. C# - 지연 실행이 꼭 필요한 상황이 아니라면 singleton 패턴에서 DCLP보다는 static 초기화를 권장파일 다운로드1
12465정성태12/29/20201068.NET Framework: 987. .NET Profiler - FunctionID와 연관된 ClassID를 구할 수 없는 문제
12464정성태12/29/20201130.NET Framework: 986. pptfont.exe - PPT 파일에 숨겨진 폰트 설정을 일괄 삭제
12463정성태12/29/2020994개발 환경 구성: 520. RDP(mstsc.exe)의 다중 모니터 옵션 /multimon, /span
12462정성태12/27/20201007디버깅 기술: 177. windbg - (ASP.NET 환경에서 유용한) netext 확장
12461정성태12/21/20201664.NET Framework: 985. .NET 코드 리뷰 팁 [3]
12460정성태12/18/20201325기타: 78. 도서 소개 - C#으로 배우는 암호학
1  2  3  4  5  6  7  8  9  10  [11]  12  13  14  15  ...