기억속으로 날다(Walking on Memory) : GC가 시작되는 순간에 Hang 현상

High CPU현상이 아닌 상황에서 hang Dump를 수집했는데, Lock이 존재할 것이라고 생각했다.

0:100> !locks

CritSec +14ce60 at 0014ce60

WaiterWoken No

LockCount 134

RecursionCount 1

OwningThread 162c

EntryCount 0

ContentionCount 86

*** Locked

CritSec +15d558 at 0015d558

WaiterWoken No

LockCount 2

RecursionCount 1

OwningThread 8a4

EntryCount 0

ContentionCount 2

*** Locked

2개의 Lock이 보이므로, 이것들이 서로서로 deadlock을 유발하겠구나 하고 쉽게 생각했지만, 그렇지 않았다. 일단, 134개의 lock을 잡고 있는 162c의 Thread는 GC Thread였다.

0:100> ~~[162c]s

eax=00000001 ebx=04fce8c0 ecx=002381e8 edx=7c96ed64 esi=04fce8c4 edi=7ffd4000

eip=7c96ed64 esp=04fce874 ebp=04fce91c iopl=0 nv up ei pl zr na pe nc

cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246

ntdll!KiFastSystemCallRet:

7c96ed64 c3 ret

0:014> kb

ChildEBP RetAddr Args to Child

04fce870 7c962104 7c82716b 00000002 04fce8c0 ntdll!KiFastSystemCallRet

04fce874 7c82716b 00000002 04fce8c0 00000001 ntdll!NtWaitForMultipleObjects+0xc

04fce91c 7c821095 00000002 04fcea5c 00000000 kernel32!WaitForMultipleObjectsEx+0x11a

04fce938 79248be3 00000002 04fcea5c 00000000 kernel32!WaitForMultipleObjects+0x18

04fceb70 791e0723 00000002 00000000 00000000 mscorwks!Thread::SysSuspendForGC+0x248

04fceb88 792144f9 00000001 00000000 00000000 mscorwks!GCHeap::SuspendEE+0xcf

04fceba4 7924199e 00000000 00000000 00000e44 mscorwks!GCHeap::GarbageCollectGeneration+0x103

04fcebd4 791b3868 00238a08 00000e44 00000000 mscorwks!gc_heap::allocate_more_space+0x13a

04fcedf8 791b300a 00238a08 00000e44 00000000 mscorwks!GCHeap::Alloc+0x5f

04fcee0c 791dd118 00000e44 00000000 00000000 mscorwks!Alloc+0x3a

04fcee2c 791dd0b9 00bd0088 0000071c 00000000 mscorwks!FastAllocatePrimitiveArray+0x45

04fceeac 00bc1336 00000000 0000071c 0c67ab58 mscorwks!JIT_NewArr1+0xbb

WARNING: Frame IP not in any known module. Following frames may be wrong.

00000000 00000000 00000000 00000000 00000000 0xbc1336

이것은 아마도 Memory Allocation중에 적정한 Size의 Memory를 할당받지 못했나 보다. 하여, GC가 수행되기 위해 EE를 Suspend 를 하고 있다. 만일, 이 Thread가 진행되지 않는 다면, 이는 Suspend 되지 않는 Thread가 존재할 것이라 믿는 다. 그 전에 대부분의 Thread가 아래와 같은 Thread와 동일한 형태였다.

0:014> ~100s

eax=000019d6 ebx=00000000 ecx=00000000 edx=630d5cb8 esi=0014ce60 edi=000005b8

eip=7c96ed64 esp=10c0f9bc ebp=10c0f9f8 iopl=0 nv up ei pl zr na pe nc

cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246

ntdll!KiFastSystemCallRet:

7c96ed64 c3 ret

0:100> kb

ChildEBP RetAddr Args to Child

10c0f9b8 7c962114 7c97972f 000005b8 00000000 ntdll!KiFastSystemCallRet

10c0f9bc 7c97972f 000005b8 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc

10c0f9f8 7c979640 00000000 00000004 0000000a ntdll!RtlpWaitOnCriticalSection+0x19c

10c0fa18 791b6ffc 0014ce60 10c0fa4c 79268960 ntdll!RtlEnterCriticalSection+0xa8

10c0fa24 79268960 0014ce60 00000000 0fdc43c8 mscorwks!EE_EnterCriticalSection+0xc

10c0fa38 791b48f8 7c828ce5 0fdc43c8 7c82bccd mscorwks!BaseCrst::Enter+0x8a

10c0fa4c 791d09e8 00000000 00000001 0fdc43c8 mscorwks!ThreadStore::LockThreadStore+0x9d

10c0fa60 791d0abb 0fdc43c8 00000000 7c82bbcd mscorwks!ThreadStore::AddThread+0xd

10c0fa88 7929c0de 0020de28 10c0fb48 7931712e mscorwks!SetupThread+0x103

10c0fa94 7931712e 00000000 0020de28 0020de28 mscorwks!SetupThreadPoolThread+0x15

10c0fb48 79317611 0017cd48 00000001 00000001 mscorwks!AddTimerCallbackEx+0x16

10c0fb5c 792eebc6 0017cd48 00000001 792eebb7 mscorwks!AddTimerCallback+0x10

10c0fb70 792ee6ca 0020de28 0512fe38 793fa170 mscorwks!ThreadpoolMgr::AsyncTimerCallbackCompletion+0xf

10c0fb84 792ee8c3 0512fe38 00000000 792ee79a mscorwks!ThreadpoolMgr::ExecuteWorkRequest+0x19

10c0fba4 792edfdb 00000000 00000014 10c0fbdc mscorwks!ThreadpoolMgr::WorkerThreadStart+0x129

10c0ffb8 7c8260b9 001a8488 00000000 00000000 mscorwks!ThreadpoolMgr::intermediateThreadProc+0x44

10c0ffec 00000000 792edf97 001a8488 00000000 kernel32!BaseThreadStart+0x34

0:100> dc 0014ce60

0014ce60 0014cf80 fffffde6 00000001 0000162c ............,...

0014ce70 000005b8 00000000 0014cfa8 ffffffff ................

0014ce80 00000000 00000000 00000000 00000000 ................

0014ce90 0015d610 0014ce90 00238a40 00000008 ........@.#.....

0014cea0 00000000 00000006 00000000 00000001 ................

0014ceb0 00000000 00000000 00000000 00000000 ................

0014cec0 00000000 002389d0 0000162c 00000111 ......#.,.......

0014ced0 00100010 000c01b6 003a0063 0077005c ........c.:.\.w.

ntdll!RtlEnterCriticalSection Function이 우리가 흔히 알고 있는 EnterCriticalSection 함수와 유사하다면, 첫번째 파라메터는 Critical Section Object일 것이다. Binary 를 살펴보면, 0xc offset에 162c 라는 값이 들어 온다. 이미 살펴 본봐 이는 !lock에서 보여주었던 GC Thread의 ThreadID와 동일하다. 아마도, 해당 Critical Section의 Owner를 보여주는 것으로 보인다.

결국, GC Thread가 Suspend Wait 하고 있는 이유를 밝히는 것이 중요하다. 아쉽게도 !lock에서 보여준 2번째 Thread의 Owner는 Orphan Thread임이 밝혀졌다.

0:100> ~~[8a4]d

^ Illegal thread error in '~~[8a4]d'

0:100> ~ <<< ALL thread를 살펴볼 수 있으나, ThreadID가 8a4 인 놈을 찾을 수 없다.

그리고, 중요한 것은 다음.

0:100> !threads

Loaded Son of Strike data table version 5 from "C:\WINDOWS\Microsoft.NET\Framework\v1.1.4322\mscorwks.dll"

ThreadCount: 8

UnstartedThread: 0

BackgroundThread: 6

PendingThread: 0

DeadThread: 1

PreEmptive GC Alloc Lock

ID ThreadOBJ State GC Context Domain Count APT Exception

0 0x6928 0x0015d5a0 0xa020 Enabled 0x00000000:0x00000000 0x0014c130 0 MTA

2 0x86c 0x00155508 0xb220 Enabled 0x00000000:0x00000000 0x0014c130 0 MTA (Finalizer)

3 0x750 0x00194cf0 0x1220 Enabled 0x0c484a6c:0x0c486140 0x0014c130 0 Ukn

5 0x70fc 0x001820d8 0x2001220 Enabled 0x00000000:0x00000000 0x0014c130 0 Ukn

10 0x51f8 0x001a6c48 0x800222 Disabled 0x0c3a7c60:0x0c3a7c70 0x0014c130 0 MTA (Threadpool Completion Port)

XXX 0 0x001bbfc0 0x800820 Enabled 0x00000000:0x00000000 0x0014c130 1 MTA (Threadpool Completion Port)

13 0x63e8 0x002381e8 0x800222 Disabled 0x0c489bf0:0x0c48a140 0x0014c130 0 MTA (Threadpool Completion Port)

14 0x162c 0x002389d0 0x800220 Disabled 0x0c6ae3d8:0x0c6af044 0x0014c130 1 MTA (GC) (Threadpool Completion Port)

보면, PreEmptive GC에 Enabled 되지 않은 Thread가 GC Thread 포함해서 3개가 존재한다. 14번 Thread인 GC Thread는 다른 모든 Thread가 Suspend될 때까지 기다릴 터이다. 그럼, 10번, 13번 Thread가 왜 Disabled 인지 확인할 필요가 있다.

0:100> ~10s

eax=00003a24 ebx=00000000 ecx=00000000 edx=5dc101c9 esi=0015d558 edi=00000498

eip=7c96ed64 esp=0488df7c ebp=0488dfb8 iopl=0 nv up ei pl zr na pe nc

cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246

ntdll!KiFastSystemCallRet:

7c96ed64 c3 ret

0:010> kb

ChildEBP RetAddr Args to Child

0488df78 7c962114 7c97972f 00000498 00000000 ntdll!KiFastSystemCallRet

0488df7c 7c97972f 00000498 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc

0488dfb8 7c979640 00000000 00000004 0000000a ntdll!RtlpWaitOnCriticalSection+0x19c

0488dfd8 791b6ffc 0015d558 0488e008 79268960 ntdll!RtlEnterCriticalSection+0xa8

0488dfe4 79268960 0015d558 0488e15c 0488e15c mscorwks!EE_EnterCriticalSection+0xc

0488dff8 79254d88 0488e15c 0488e140 0488e044 mscorwks!BaseCrst::Enter+0x8a

0488e008 7921d09b 0488e140 0488e6b0 0488e15c mscorwks!CPFH_HandleManagedFault+0x61

0488e044 7921d135 0488e140 0488e6b0 0488e15c mscorwks!GetPrevSEHRecord+0x703

0488e05c 7c96eeca 0488e140 0488e6b0 0488e15c mscorwks!COMPlusFrameHandler+0x3d

0488e080 7c96ee9b 0488e140 0488e6b0 0488e15c ntdll!ExecuteHandler2+0x26

0488e128 7c96ecd6 04888000 0488e15c 0488e140 ntdll!ExecuteHandler+0x24

0488e128 04dece25 04888000 0488e15c 0488e140 ntdll!KiUserExceptionDispatcher+0xe

WARNING: Frame IP not in any known module. Following frames may be wrong.

0488e424 0488e650 0c3a7468 0c3a7504 0c3a4af8 0x4dece25

00000000 00000000 00000000 00000000 00000000 0x488e650

눈에 띄는 것은 KiUserExceptionDispatcher . (http://byung.egloos.com/4710539) 이것은 Exception이 발생한 경우이다. 해당 함수의 Stack을 살펴보면, 아래와 같은 몇몇 정보를 얻을 수 있다.

0:010> dc 0488e128

0488e128 0c3a7ac8 7c96ecd6 04888000 0488e15c .z:....|....\...

0488e138 0488e140 0488e15c c0000005 00000000 @...\........... <<< c0000005: Access Violation

0488e148 00000000 04dece25 00000002 00000000 ....%........... <<< 04dece25: Exception Address

0488e158 00000000 0001003f 00000000 00000000 ....?........... <<< 1003f Context Flags

0488e168 00000000 00000000 00000000 00000000 ................

0488e178 ffff027f ffff4020 ffffffff 00bc4c08 .... @.......L..

0488e188 00ca001b 0488e6d8 ffff0023 00000000 ........#.......

0488e198 00000000 00000000 00000000 00000000 ................

결국, 해당 Thread는 04dece25 에서 Access Violation 에 대한 Exception으로 인해 GC에 의해 Suspend 되지 않은 것으로 보인다. 이는 Orphan Thread와 관련이 있을 수도 있다. 임의의 Orphan Thread (Thread ID:8a4)가 Critical Section Lock을 잡고 Terminated 되었기 때문에 해당 Exception Thread에서 Critical Section Lock이 걸려있을 수도 있다. 그리고, 추가적으로 13번 Thread 역시 10번 Thread와 동일한 Exception Thread이다.

0:013> kb

ChildEBP RetAddr Args to Child

00d4e5f0 7c962114 7c97972f 00000498 00000000 ntdll!KiFastSystemCallRet

00d4e5f4 7c97972f 00000498 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc

00d4e630 7c979640 00000000 00000004 0000000a ntdll!RtlpWaitOnCriticalSection+0x19c

00d4e650 791b6ffc 0015d558 00d4e680 79268960 ntdll!RtlEnterCriticalSection+0xa8

00d4e65c 79268960 0015d558 00d4e7d4 00d4e7d4 mscorwks!EE_EnterCriticalSection+0xc

00d4e670 79254d88 00d4e7d4 00d4e7b8 00d4e6bc mscorwks!BaseCrst::Enter+0x8a

00d4e680 7921d09b 00d4e7b8 00d4ed28 00d4e7d4 mscorwks!CPFH_HandleManagedFault+0x61

00d4e6bc 7921d135 00d4e7b8 00d4ed28 00d4e7d4 mscorwks!GetPrevSEHRecord+0x703

00d4e6d4 7c96eeca 00d4e7b8 00d4ed28 00d4e7d4 mscorwks!COMPlusFrameHandler+0x3d

00d4e6f8 7c96ee9b 00d4e7b8 00d4ed28 00d4e7d4 ntdll!ExecuteHandler2+0x26

00d4e7a0 7c96ecd6 00d4d000 00d4e7d4 00d4e7b8 ntdll!ExecuteHandler+0x24

00d4e7a0 04dece25 00d4d000 00d4e7d4 00d4e7b8 ntdll!KiUserExceptionDispatcher+0xe

WARNING: Frame IP not in any known module. Following frames may be wrong.

00d4ecc8 00e3b502 00d4ed10 00fbcda8 00d4ed28 0x4dece25

00000000 00000000 00000000 00000000 00000000 0xe3b502

0:013> dc 00d4e7a0

00d4e7a0 00d4ecc8 7c96ecd6 00d4d000 00d4e7d4 .......|........

00d4e7b0 00d4e7b8 00d4e7d4 c0000005 00000000 ................

00d4e7c0 00000000 04dece25 00000002 00000000 ....%........... << Exception Address가 10번 Thread와 동일한 위치!!

00d4e7d0 00000000 0001003f 00000000 00000000 ....?...........

00d4e7e0 00000000 00000000 00000000 00000000 ................

00d4e7f0 ffff027f ffff0000 ffffffff 00bc4c08 .............L..

00d4e800 00ca001b 00d4ecd8 ffff0023 00000000 ........#.......

00d4e810 00000000 00000000 00000000 00000000 ................

그러므로, Orphan Thread 역시 이와 같은 Exception에 문제가 되는 것은 아닌 지 의심해 본다. 결국, 해당 GC suspend Hang은 Exception에 대한 Fix가 우선적으로 처리되는 것이 필요하며, Orphan Thread를 위해 1^st chance exception에 대한 추가적인 메모리 덤프를 분석해 볼 필요도 있을 지 모른다.

추가적으로 Exception Address의 Assembly code를 !u (해당 Thread는 managed thread stack을 보여줬다.) 를 통해 확인해 볼 필요가 있겠다. 여기서 또한, .cxr 을 이용하여 (Context Flags의 address pointer 를 이용) Context switch 하여 Exception 발생 Thread Stack으로 이동할 필요도 있을 것이다. 이하 생략한다. 단지, 해당 Process의 hang 상태를 확인하는 과정으로써 Thread Stack의 Pattern이나 분석 과정을 흩어보는 것으로 마무리 한다.