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 유에 속하는 것이라서,
시스템 부하 없이 가능할 것 같아 테스트를 해봤습니다. 이름이 유추하는 것에 따라, 각각의 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://learn.microsoft.com/en-us/dotnet/api/system.gc.trystartnogcregion
GC.EndNoGCRegion Method
; https://learn.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://learn.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로 이어지는 듯합니다. 물론, 테스트를 위한 응용 프로그램이어서 약간 복잡하긴 했지만... 그래도 저 오류가 발생하는 것은 심각할 수밖에 없습니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]