windbg - Thread.Suspend 호출 시 응용 프로그램 hang 현상에 대한 덤프 분석
지난 글에서, Thread.Suspend와 GC의 조합에 따른 hang 현상을 설명했습니다.
C# - Thread.Suspend 호출 시 응용 프로그램 hang 현상
; https://www.sysnet.pe.kr/2/0/11473
그렇다면, 저런 현상을 겪고 있을 때의 덤프를 분석하는 경우 어떤 식의 패턴들이 나타날까요? 이번 글은 위의 예제를 실행해 멈췄을 때 덤프를 떠서 분석합니다.
제 경우에 덤프 파일을 구하면 우선 가장 먼저 하는 작업이 Debug Diagnostic Tool로 돌려 보는 것입니다.
DebugDiag 1.1을 사용한 덤프 분석
; https://www.sysnet.pe.kr/2/0/1026
Debug Diagnostic Tool v2 Update 2
; https://www.microsoft.com/en-us/download/details.aspx?id=49924
그럼 대강의 모습이 나오고, 구체적인 부분만 windbg를 이용하면 되기 때문입니다. 실제로 이번 덤프를 돌려 보면 다음과 같은 내용을 얻을 수 있습니다.
The following threads in ctorHang.dmp are waiting for .net garbage collection to finish. The current set of scripts were not able to determine which thread induced GC
( 0 14 16 17 )
14.29% of threads blocked (4 threads)
즉, 4개의 스레드가 GC가 끝나기만을 기다리고 있는 것입니다. 실제로 0, 14, 16, 17번 스레드의 native call stack을 보면 다음과 같은 함수 호출을 포함하고 있는 것을 확인할 수 있습니다.
ntdll!NtWaitForSingleObject+c
KERNELBASE!WaitForSingleObjectEx+99
clr!CLREventWaitHelper2+33
clr!CLREventWaitHelper+2a
clr!CLREventBase::WaitEx+152
clr!SVR::gc_heap::wait_for_gc_done+59
clr!SVR::gc_heap::try_allocate_more_space+1c
clr!SVR::gc_heap::allocate_more_space+35
clr!SVR::GCHeap::Alloc+90
clr!Alloc+87
clr!FastAllocatePrimitiveArray+101
...[생략]...
함수의 이름만으로도, 0, 14, 16, 17번 스레드가 관리 메모리를 요구하는 코드(GCHeap::Alloc)가 수행되었지만 현재 GC가 구동을 시작했기 때문에 그것을 기다리는 중(gc_heap::wait_for_gc_done)임을 알 수 있습니다.
그러니까, GCHeap::Alloc, try_allocate_more_space, allocate_more_space로 이어지는 콜스택을 가진 스레드들은 모두 GC가 끝나기를 대기하고 있는 것입니다.
GC를 기다리는 스레드가 있다면, 어디엔가 GC를 유발한 스레드도 있을 것입니다. Debug Diagnostic Tool의 분석 결과를 보면 다음의 호출 스택을 보이는 것이 있습니다.
Thread 15 - System ID 20980
...[생략]...
ntdll!NtWaitForSingleObject+c
KERNELBASE!WaitForSingleObjectEx+99
clr!CLREventWaitHelper2+33
clr!CLREventWaitHelper+2a
clr!CLREventBase::WaitEx+152
clr!CLREventBase::Wait+1a
clr!Thread::WaitSuspendEventsHelper+8a
clr!Thread::WaitSuspendEvents+14
clr!Thread::RareEnablePreemptiveGC+98
clr!SVR::gc_heap::enable_preemptive+25
clr!SVR::gc_heap::trigger_gc_for_alloc+23
clr!SVR::gc_heap::try_allocate_more_space+15a
clr!SVR::gc_heap::allocate_more_space+35
clr!SVR::gc_heap::allocate_large_object+83
clr!SVR::GCHeap::Alloc+b3
clr!Alloc+87
clr!FastAllocatePrimitiveArray+101
clr!JIT_NewArr1+126
[[HelperMethodFrame]]
ConsoleApp1.Program.threadFunc()+70
...[생략]...
즉 15번 스레드는 GCHeap::Alloc을 시도했는데 관리 힙의 상태가 GC 임계점에 다다랐기 때문에 GC 작업을 시작(trigger_gc_for_alloc)한 것입니다. 그런데 이 스레드가 GC 작업을 완료하고 있지 못하기 때문에 0, 14, 16, 17번 스레드도 hang이 걸린 것입니다.
15번 스레드의 호출 스택에 따르면 "Preemptive"라는 단어가 있는 것으로 봐서 아마도 다른 스레드들이 Preemptive 상태인지 확인하는 작업에 있음을 짐작케 합니다. 역시 Debug Diagnostic Tool 도구의 분석 화면에 있는 ".NET Threads Summary" 영역을 보면,
.NET Threads Summary
Total Threads: 0
Running Threads: 0
Idle Threads: 0
Max Threads: 0
Min Threads: 0
Debugger Thread ID Managed Thread ID OS Thread ID Thread Object GC Mode Domain Lock Count Apt Exception
0 1 17112 2d400e0 Preemptive 2d31ea0 0 MTA
12 2 18788 2da74c8 Preemptive 2d31ea0 0 MTA (Finalizer)
14 3 13124 2dc54d8 Preemptive 2d31ea0 0 MTA
15 4 20980 2dc5e08 Preemptive 2d31ea0 0 MTA (User Suspended)
16 5 19236 2dc6b48 Preemptive 2d31ea0 0 MTA
17 6 1212 2dc75d8 Preemptive 2d31ea0 0 MTA
18 7 12772 2dd0860 Preemptive 2d31ea0 0 Unknown
19 8 22500 2dd1190 Preemptive 2d31ea0 0 Unknown
20 9 9676 2dd1ac0 Preemptive 2d31ea0 0 Unknown
21 10 10740 2dd63f8 Preemptive 2d31ea0 0 Unknown
22 11 12124 2ddb538 Preemptive 2d31ea0 0 Unknown
23 12 21100 2ddbe68 Preemptive 2d31ea0 0 Unknown
24 13 21712 2ddd690 Preemptive 2d31ea0 0 Unknown
25 14 2248 2ddeeb8 Preemptive 2d31ea0 0 Unknown
모든 스레드의 GC Mode가 Preemptive인 것을 알 수 있습니다. 즉, 15번 스레드가 멈춰 있는 것은 다른 스레드들이 Preemptive로 진입하기를 기다리고 있지는 않음을 의미합니다.
이제 windbg를 열고 해당 덤프 파일로부터 15번 스레드의 정보를 얻어와야 합니다.
0:000> !threads
ThreadCount: 14
UnstartedThread: 0
BackgroundThread: 13
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 42d8 02d400e0 2a020 Preemptive 050211BC:00000000 02d31ea0 0 MTA
12 2 4964 02da74c8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA (Finalizer)
14 3 3344 02dc54d8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
15 4 51f4 02dc5e08 ab224 Preemptive 00000000:00000000 02d31ea0 0 MTA
16 5 4b24 02dc6b48 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
17 6 4bc 02dc75d8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
18 7 31e4 02dd0860 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
19 8 57e4 02dd1190 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
20 9 25cc 02dd1ac0 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
21 10 29f4 02dd63f8 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
22 11 2f5c 02ddb538 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
23 12 526c 02ddbe68 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
24 13 54d0 02ddd690 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
25 14 8c8 02ddeeb8 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
15번 스레드의 State가 ab224이고 이것은
threadstate 명령어로 풀어낼 수 있습니다.
0:000> !threadstate ab224
User Suspend Pending
Legal to Join
Background
CLR Owns
CoInitialized
In Multi Threaded Apartment
Fully initialized
Sync Suspended
즉, 현재 Suspend 상태에 있는 것입니다. 여기서 호출 스택을 구하기 위해 Suspend로 바뀌었음을 Debug Diagnostic Tool의 또 다른 호출 스택 출력을 보고 짐작할 수 있습니다.
Thread 0 - System ID 17112
...[생략]...
ntdll!NtWaitForSingleObject+c
KERNELBASE!WaitForSingleObjectEx+99
clr!CLREventWaitHelper2+33
clr!CLREventWaitHelper+2a
clr!CLREventBase::WaitEx+152
clr!SVR::gc_heap::wait_for_gc_done+59
clr!SVR::gc_heap::try_allocate_more_space+1c
clr!SVR::gc_heap::allocate_more_space+35
clr!SVR::GCHeap::Alloc+90
clr!Alloc+87
clr!FastAllocatePrimitiveArray+101
clr!UnframedAllocatePrimitiveArray+50
clr!AllocatePrimitiveArray+1b
[[HelperMethodFrame_2OBJ] (System.Diagnostics.StackTrace.GetStackFramesInternal)] System.Diagnostics.StackTrace.GetStackFramesInternal(System.Diagnostics.StackFrameHelper, Int32, Boolean, System.Exception)
[[GCFrame]]
mscorlib_ni!System.Diagnostics.StackFrameHelper.InitializeSourceInfo(Int32, Boolean, System.Exception)+3d
mscorlib_ni!System.Diagnostics.StackFrameHelper.InitializeSourceInfo(Int32, Boolean, System.Exception)+3d
mscorlib_ni!System.Diagnostics.StackTrace.CaptureStackTrace(Int32, Boolean, System.Threading.Thread, System.Exception)+4c
mscorlib_ni!System.Diagnostics.StackTrace.CaptureStackTrace(Int32, Boolean, System.Threading.Thread, System.Exception)+4c
mscorlib_ni!System.Diagnostics.StackTrace..ctor(System.Threading.Thread, Boolean)+1d
...[생략]...
100% 확신을 얻기 위해, 그럼 저 스레드 0번에서 Suspend를 호출한 대상이 15번 스레드인지 확인해 볼 차례입니다. 우선 문맥 전환을 하고,
0:000> ~0s
eax=00000000 ebx=02d400e0 ecx=0afd0c10 edx=00000000 esi=00000000 edi=00000290
eip=771ee7ac esp=00afe774 ebp=00afe7e4 iopl=0 nv up ei pl nz na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000206
ntdll!NtWaitForSingleObject+0xc:
771ee7ac c20c00 ret 0Ch
(32비트이기 때문에 결과가 잘 나올 것으로 기대되는) -a 옵션을 주면 다음과 같이 인자 값을 확인할 수 있습니다.
0:000> !clrstack -a
OS Thread Id: 0x42d8 (0)
Child SP IP Call Site
00afea3c 771ee7ac [GCFrame: 00afea3c]
00afe9e4 771ee7ac [HelperMethodFrame_2OBJ: 00afe9e4] System.Diagnostics.StackTrace.GetStackFramesInternal(System.Diagnostics.StackFrameHelper, Int32, Boolean, System.Exception)
00afefb8 70f062f1 System.Diagnostics.StackFrameHelper.InitializeSourceInfo(Int32, Boolean, System.Exception) [f:\dd\ndp\clr\src\BCL\system\diagnostics\stacktrace.cs @ 109]
PARAMETERS:
this (<CLR reg>) = 0x0502114c
iSkip = <no data>
fNeedFileInfo (<CLR reg>) = 0x00000000
exception = <no data>
LOCALS:
<no data>
<no data>
<no data>
<no data>
<no data>
00afeff4 70f0607c System.Diagnostics.StackTrace.CaptureStackTrace(Int32, Boolean, System.Threading.Thread, System.Exception) [f:\dd\ndp\clr\src\BCL\system\diagnostics\stacktrace.cs @ 521]
PARAMETERS:
this (0x00afeff8) = 0x05021138
iSkip = <no data>
fNeedFileInfo (0x00aff02c) = 0x00000000
targetThread = <no data>
e (0x00aff024) = 0x00000000
LOCALS:
0x00afeff4 = 0x0502114c
<no data>
<no data>
<no data>
<no data>
00aff030 71698b61 System.Diagnostics.StackTrace..ctor(System.Threading.Thread, Boolean) [f:\dd\ndp\clr\src\BCL\system\diagnostics\stacktrace.cs @ 475]
PARAMETERS:
this = <no data>
targetThread = <no data>
needFileInfo = <no data>
00aff038 04a60917 ConsoleApp1.Program.GetCallStack(System.Threading.Thread) [E:\thread_callstack_dump_x86\ConsoleApp1\ctorHang\Program.cs @ 60]
PARAMETERS:
t (0x00aff050) = 0x0ad637ac
LOCALS:
0x00aff04c = 0x00000000
0x00aff048 = 0x00000000
...[생략]...
그래서 0x0ad637ac 값을 조사해 보면,
0:000> !DumpObj 0ad637ac
Name: System.Threading.Thread
MethodTable: 710707e4
EEClass: 70bf9078
Size: 52(0x34) bytes
File: C:\WINDOWS\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
71054f18 400190a 4 ....Contexts.Context 0 instance 00000000 m_Context
710649b0 400190b 8 ....ExecutionContext 0 instance 00000000 m_ExecutionContext
7106fbf0 400190c c System.String 0 instance 0ad63814 m_Name
7107137c 400190d 10 System.Delegate 0 instance 00000000 m_Delegate
71072c44 400190e 14 ...ation.CultureInfo 0 instance 00000000 m_CurrentCulture
71072c44 400190f 18 ...ation.CultureInfo 0 instance 00000000 m_CurrentUICulture
7106ff90 4001910 1c System.Object 0 instance 00000000 m_ThreadStartArg
71065d9c 4001911 20 System.IntPtr 1 instance 2dc5e08 DONT_USE_InternalThread
71071a90 4001912 24 System.Int32 1 instance 2 m_Priority
71071a90 4001913 28 System.Int32 1 instance 4 m_ManagedThreadId
71063884 4001914 2c System.Boolean 1 instance 1 m_ExecutionContextBelongsToOuterScope
7105b870 4001915 6e8 ...LocalDataStoreMgr 0 shared static s_LocalDataStoreMgr
>> Domain:Value 02d31ea0:NotInit <<
71a822ec 4001917 6ec ...eInfo, mscorlib]] 0 shared static s_asyncLocalCurrentCulture
>> Domain:Value 02d31ea0:NotInit <<
71a822ec 4001918 6f0 ...eInfo, mscorlib]] 0 shared static s_asyncLocalCurrentUICulture
>> Domain:Value 02d31ea0:NotInit <<
71062890 4001916 c ...alDataStoreHolder 0 shared TLstatic s_LocalDataStore
>> Thread:Value <<
관리 스레드 ID가 4번에 해당하는 스레드가 호출 스택을 얻기 위해 Suspend되었다고 확인이 됩니다. 그리고 관리 스레드 4번은,
0:000> !threads
ThreadCount: 14
UnstartedThread: 0
BackgroundThread: 13
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 42d8 02d400e0 2a020 Preemptive 050211BC:00000000 02d31ea0 0 MTA
12 2 4964 02da74c8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA (Finalizer)
14 3 3344 02dc54d8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
15 4 51f4 02dc5e08 ab224 Preemptive 00000000:00000000 02d31ea0 0 MTA
16 5 4b24 02dc6b48 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
17 6 4bc 02dc75d8 2b220 Preemptive 00000000:00000000 02d31ea0 0 MTA
18 7 31e4 02dd0860 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
19 8 57e4 02dd1190 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
20 9 25cc 02dd1ac0 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
21 10 29f4 02dd63f8 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
22 11 2f5c 02ddb538 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
23 12 526c 02ddbe68 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
24 13 54d0 02ddd690 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
25 14 8c8 02ddeeb8 21220 Preemptive 00000000:00000000 02d31ea0 0 Ukn
Debugger의 15번 스레드에 해당함을 확인하게 됩니다. 그렇다면 호출 스택을 얻으려던 0번 스레드는 15번 스레드를 Suspend 시킨 후, 왜 다시 Resume을 하지 못했던 걸까요? 역시 0번 스레드의 호출 스택에서 그 해답을 찾을 수 있습니다.
ntdll!NtWaitForSingleObject+c
KERNELBASE!WaitForSingleObjectEx+99
clr!CLREventWaitHelper2+33
clr!CLREventWaitHelper+2a
clr!CLREventBase::WaitEx+152
clr!SVR::gc_heap::wait_for_gc_done+59
clr!SVR::gc_heap::try_allocate_more_space+1c
clr!SVR::gc_heap::allocate_more_space+35
clr!SVR::GCHeap::Alloc+90
clr!Alloc+87
clr!FastAllocatePrimitiveArray+101
clr!UnframedAllocatePrimitiveArray+50
clr!AllocatePrimitiveArray+1b
[[HelperMethodFrame_2OBJ] (System.Diagnostics.StackTrace.GetStackFramesInternal)] System.Diagnostics.StackTrace.GetStackFramesInternal(System.Diagnostics.StackFrameHelper, Int32, Boolean, System.Exception)
[[GCFrame]]
mscorlib_ni!System.Diagnostics.StackFrameHelper.InitializeSourceInfo(Int32, Boolean, System.Exception)+3d
mscorlib_ni!System.Diagnostics.StackFrameHelper.InitializeSourceInfo(Int32, Boolean, System.Exception)+3d
mscorlib_ni!System.Diagnostics.StackTrace.CaptureStackTrace(Int32, Boolean, System.Threading.Thread, System.Exception)+4c
mscorlib_ni!System.Diagnostics.StackTrace.CaptureStackTrace(Int32, Boolean, System.Threading.Thread, System.Exception)+4c
즉, Suspend 시킨 후 GetStackFramesInternal을 호출하는 과정에서 내부적으로 관리 힙으로부터 메모리를 요구하고 있기 때문에 15번 스레드가 착수한 GC 작업을 0번 스레드도 기다리게 된 것입니다.
이로 인해, 이후 실행되는 모든 관리 스레드들은 new와 관련된 작업으로 진입하기만 하면 멈춰버리게 되고 결국 응용 프로그램은 "응답 없음" 상태로 빠지게 됩니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]