windbg 분석 사례 - x86 ASP.NET 웹 응용 프로그램의 CPU 100% 현상 (4)
이번 글은 아래의 내용에 대한 32비트 버전입니다. ^^;
windbg 분석 사례 - ASP.NET 웹 응용 프로그램의 CPU 100% 현상 (3)
; https://www.sysnet.pe.kr/2/0/11588
CPU high 현상이 발생하면, 덤프 파일로부터 가장 먼저 확인할 것은 스레드별 CPU 사용 시간입니다.
// https://learn.microsoft.com/en-us/windows-hardware/drivers/debuggercmds/-runaway
0:000> !runaway
User Mode Time
Thread Time
71:2a50 0 days 0:06:01.546
77:21a8 0 days 0:05:32.125
75:10b8 0 days 0:04:36.859
...[생략]...
49:2670 0 days 0:00:00.015
36:7e4 0 days 0:00:00.015
10:660 0 days 0:00:00.015
ASP.NET처럼 다중 스레드를 사용하는 환경에서 다른 일반적인 것과 비교해 큰 (위의 경우 저렇게 6분이 넘는) 동작 시간이라면 거의 대부분 무한 루프(또는 그에 준하는 무거운 작업)로 인한 CPU high 현상이라고 볼 수 있습니다. 이후 가장 의심이 되는 최상단 스레드의 호출 스택을 확인하고,
// 문제가 되는 스레드로 문맥 변경
0:071> ~71s
eax=ffffffff ebx=00000025 ecx=0bb1662c edx=0ba5da08 esi=00000009 edi=0ba5d9e0
eip=1ea0de53 esp=2b80d944 ebp=2b80d960 iopl=0 nv up ei ng nz na pe cy
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000287
System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0x53:
1ea0de53 3b45f0 cmp eax,dword ptr [ebp-10h] ss:002b:2b80d950=0dd22b7a
// 호출 스택 확인
0:071> !clrstack
OS Thread Id: 0x2a50 (71)
Child SP IP Call Site
2b80d944 1ea0de53 System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
2b80d968 1f6230f7 System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)
2b80d97c 1f62220c System.Web.HttpCookieCollection.Get(System.String)
2b80d994 2093cf90 MyWebApp.Web.CheckCookie()
...[생략]...
2b80e6f4 1ea2fda0 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
2b80e7c8 073edfa6 [ContextTransitionFrame: 2b80e7c8]
마찬가지로 다른 스레드 77, 75 등의 호출 스택을 확인해 문제를 진단할 수 있습니다. 제가 분석한 덤프는 분 단위의 실행 시간을 갖는 스레드의 호출 스택이 모두 HashSet.Contains에서 돌고 있었는데요, 그런 걸로 봐서는 (아마도) 해당 메서드에서 무한 루프에 빠졌음을 한 번 더 확신할 수 있게 됩니다.
자, 그럼 HashSet.Contains 메서드의 코드를 역어셈블 해볼까요?
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int num = this.InternalGetHashCode(item);
for (int i = this.m_buckets[num % this.m_buckets.Length] - 1; i >= 0; i = this.m_slots[i].next)
{
if (this.m_slots[i].hashCode == num && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
다행히 복잡하지 않아서 좋습니다. ^^ 그리고 jitted 상태의 코드를 함께 봐야 하는데요,
0:071> !U 1ea0de53
Normal JIT generated code
System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
Begin 1ea0de00, size c4
1ea0de00 55 push ebp
1ea0de01 8bec mov ebp,esp
1ea0de03 57 push edi
1ea0de04 56 push esi
1ea0de05 53 push ebx
1ea0de06 83ec10 sub esp,10h
1ea0de09 8955e8 mov dword ptr [ebp-18h],edx
1ea0de0c 8bf9 mov edi,ecx
1ea0de0e 837f0400 cmp dword ptr [edi+4],0
1ea0de12 0f849c000000 je System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xb4 (1ea0deb4)
1ea0de18 8bcf mov ecx,edi
1ea0de1a 8b55e8 mov edx,dword ptr [ebp-18h]
1ea0de1d e88e4f99fe call System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].InternalGetHashCode(System.__Canon) (1d3a2db0)
1ea0de22 8945f0 mov dword ptr [ebp-10h],eax
1ea0de25 8b4f04 mov ecx,dword ptr [edi+4]
1ea0de28 8b5704 mov edx,dword ptr [edi+4]
1ea0de2b 8b5a04 mov ebx,dword ptr [edx+4]
1ea0de2e 99 cdq
1ea0de2f f7fb idiv eax,ebx
1ea0de31 3b5104 cmp edx,dword ptr [ecx+4]
1ea0de34 0f8384000000 jae System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xbe (1ea0debe)
1ea0de3a 8b749108 mov esi,dword ptr [ecx+edx*4+8]
1ea0de3e 4e dec esi
1ea0de3f 7873 js System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xb4 (1ea0deb4)
1ea0de41 8b5708 mov edx,dword ptr [edi+8]
1ea0de44 3b7204 cmp esi,dword ptr [edx+4]
1ea0de47 7375 jae System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xbe (1ea0debe)
1ea0de49 8d0476 lea eax,[esi+esi*2]
1ea0de4c 8d448208 lea eax,[edx+eax*4+8]
1ea0de50 8b4004 mov eax,dword ptr [eax+4]
>>> 1ea0de53 3b45f0 cmp eax,dword ptr [ebp-10h]
1ea0de56 7546 jne System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0x9e (1ea0de9e)
1ea0de58 8b5f0c mov ebx,dword ptr [edi+0Ch]
1ea0de5b 8d0476 lea eax,[esi+esi*2]
1ea0de5e 8b448208 mov eax,dword ptr [edx+eax*4+8]
1ea0de62 8945e4 mov dword ptr [ebp-1Ch],eax
1ea0de65 8b0f mov ecx,dword ptr [edi]
1ea0de67 8b4120 mov eax,dword ptr [ecx+20h]
1ea0de6a 8b00 mov eax,dword ptr [eax]
1ea0de6c 8b4020 mov eax,dword ptr [eax+20h]
1ea0de6f 85c0 test eax,eax
1ea0de71 750a jne System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0x7d (1ea0de7d)
1ea0de73 ba8cc9391d mov edx,1D39C98Ch
1ea0de78 e8434bb350 call clr!JIT_GenericHandleClass (6f5429c0)
1ea0de7d 8945ec mov dword ptr [ebp-14h],eax
1ea0de80 ff75e8 push dword ptr [ebp-18h]
1ea0de83 8bcb mov ecx,ebx
1ea0de85 8b55e4 mov edx,dword ptr [ebp-1Ch]
1ea0de88 90 nop
1ea0de89 90 nop
1ea0de8a 90 nop
1ea0de8b ff10 call dword ptr [eax]
1ea0de8d 85c0 test eax,eax
1ea0de8f 740d je System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0x9e (1ea0de9e)
1ea0de91 b801000000 mov eax,1
1ea0de96 8d65f4 lea esp,[ebp-0Ch]
1ea0de99 5b pop ebx
1ea0de9a 5e pop esi
1ea0de9b 5f pop edi
1ea0de9c 5d pop ebp
1ea0de9d c3 ret
1ea0de9e 8b5708 mov edx,dword ptr [edi+8]
1ea0dea1 3b7204 cmp esi,dword ptr [edx+4]
1ea0dea4 7318 jae System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xbe (1ea0debe)
1ea0dea6 8d0476 lea eax,[esi+esi*2]
1ea0dea9 8d448208 lea eax,[edx+eax*4+8]
1ea0dead 8b7008 mov esi,dword ptr [eax+8]
1ea0deb0 85f6 test esi,esi
1ea0deb2 7d90 jge System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0x44 (1ea0de44)
1ea0deb4 33c0 xor eax,eax
1ea0deb6 8d65f4 lea esp,[ebp-0Ch]
1ea0deb9 5b pop ebx
1ea0deba 5e pop esi
1ea0debb 5f pop edi
1ea0debc 5d pop ebp
1ea0debd c3 ret
1ea0debe e88d0be250 call clr!JIT_RngChkFail (6f82ea50)
1ea0dec3 cc int 3
낯선 것치고는, 닷넷 코드와 잘 엮으면 그런대로 쉽게 분석할 수 있으니 약간의 인내심만 챙기시면 됩니다. ^^ 우선, HashSet<string>.Contains(string item)에 전달한 인자 먼저 알아내 볼까요?
public bool Contains(T item)
{
1ea0de00 55 push ebp // 함수의 prologue 코드 시작
1ea0de01 8bec mov ebp,esp
1ea0de03 57 push edi
1ea0de04 56 push esi
1ea0de05 53 push ebx
1ea0de06 83ec10 sub esp,10h // prologue 끝
1ea0de09 8955e8 mov dword ptr [ebp-18h],edx // 첫 번째 인자: *(ebp-18h) == 0b85b610 (WinDbg의 Registers 뷰에서 ebp 확인 가능)
1ea0de0c 8bf9 mov edi,ecx // 0번째 인자(this): edi == 1196074C (WinDbg의 Registers 뷰에서 edi 확인 가능)
if (this.m_buckets != null)
1ea0de0e 837f0400 cmp dword ptr [edi+4],0
1ea0de12 0f849c000000 je System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+0xb4 (1ea0deb4)
x86의 경우 ecx, edx에 처음 2개의 인자가 전달되므로, 위에서는 그 값들을 각각 edi, [ebp-18h]에 백업/저장하고 있습니다. 그렇다면 첫 번째 this에 해당하는 HashSet 인스턴스 자체와 두 번째 T item, 즉 string item의 문자열은 다음과 같이 확인할 수 있습니다.
// 첫 번째 인자 (instance 메서드이므로 첫 번째 인자는 this)
0:071> !do edi
Name: System.Collections.Generic.HashSet`1[[System.String, mscorlib]]
MethodTable: 1d073ba8
EEClass: 1cec2ed4
Size: 40(0x28) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Core\v4.0_4.0.0.0__b77a5c561934e089\System.Core.dll
Fields:
MT Field Offset Type VT Attr Value Name
1ad0a6c8 40004ce 4 System.Int32[] 0 instance 0ba5dbd0 m_buckets
1d073fc8 40004cf 8 ...non, mscorlib]][] 0 instance 0ba5da08 m_slots
0782c9b0 40004d0 14 System.Int32 1 instance 18 m_count
0782c9b0 40004d1 18 System.Int32 1 instance 27 m_lastIndex
0782c9b0 40004d2 1c System.Int32 1 instance 11 m_freeList
1ac38488 40004d3 c ...Canon, mscorlib]] 0 instance 1185813c m_comparer
0782c9b0 40004d4 20 System.Int32 1 instance 36 m_version
1b6f7820 40004d5 10 ...SerializationInfo 0 instance 00000000 m_siInfo
// 두 번째 인자
0:071> !do dwo(ebp-18)
Name: System.String
MethodTable: 0782fd98
EEClass: 0783e334
Size: 24(0x18) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: score
Fields:
MT Field Offset Type VT Attr Value Name
0782c9b0 400027b 4 System.Int32 1 instance 5 m_stringLength
0782b16c 400027c 8 System.Char 1 instance 73 m_firstChar
0782fd98 4000280 60 System.String 0 shared static Empty
>> Domain:Value 06cc28a0:NotInit 1c1cfec0:NotInit <<
보니까, HashSet에는 18개의 항목이 있음을 짐작게 합니다. 이를 바탕으로 이어지는 코드를 분석해 보면, "score" 문자열에 대한 hash 값을 구해 [ebp-10h]에 저장한다는 것에서,
this.InternalGetHashCode(item);
1ea0de18 8bcf mov ecx,edi
1ea0de1a 8b55e8 mov edx,dword ptr [ebp-18h]
1ea0de1d e88e4f99fe call System_Core!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].InternalGetHashCode(System.__Canon) (1d3a2db0)
int num =
1ea0de22 8945f0 mov dword ptr [ebp-10h],eax
num의 값도 구할 수 있게 됐습니다.
0:071> dd ebp-10h L1
2b80d950 0dd22b7a
자, 그럼 여기까지 해서 대충 다음과 같이 중간 정리가 됩니다.
public bool Contains(string item = "score")
{
if (this.m_buckets != null)
{
int hashCode = 0dd22b7a;
// for (int i = this.m_buckets[hashCode % this.m_buckets.Length] - 1; i >= 0; i = this.m_slots[i].next)
// ==> hashCode % this.m_buckets.Length
// ==> 0x0dd22b7a % 18 == 10 (0x0a)
for (int i = this.m_buckets[10] - 1; i >= 0; i = this.m_slots[i].next)
{
if ((this.m_slots[i].hashCode == 0x0dd22b7a) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
그럼 이제 최초 루프 진입 시의 i 값을 구해 볼까요? 이를 위해 m_buckets[10]의 값을 이렇게 구할 수 있습니다.
0:071> !da 0ba5dbd0
Name: System.Int32[]
MethodTable: 1ad0a6c8
EEClass: 1ad0a66c
Size: 160(0xa0) bytes
Array: Rank 1, Number of elements 37, Type Int32
Element Methodtable: 0782c9b0
[0] 0ba5dbd8
[1] 0ba5dbdc
[2] 0ba5dbe0
[3] 0ba5dbe4
[4] 0ba5dbe8
[5] 0ba5dbec
[6] 0ba5dbf0
[7] 0ba5dbf4
[8] 0ba5dbf8
[9] 0ba5dbfc
[10] 0ba5dc00
[11] 0ba5dc04
...[생략]...
[36] 0ba5dc68
0:071> !DumpVC 0782c9b0 0ba5dc00
Name: System.Int32
MethodTable: 0782c9b0
EEClass: 0783d1f0
Size: 12(0xc) 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
0782c9b0 400059a 0 System.Int32 1 instance 11 m_value
따라서 m_buckets[10]의 값은 11이고, 이 값에서 -1을 하면 10이 i의 초깃값이 됩니다. 다음은 slots[10]을 아래와 같이 구할 수 있고,
0:071> !da 0ba5da08
Name: System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]][]
MethodTable: 1d0742f0
EEClass: 1d074288
Size: 456(0x1c8) bytes
Array: Rank 1, Number of elements 37, Type VALUETYPE
Element Methodtable: 1d074248
[0] 0ba5da10
[1] 0ba5da1c
[2] 0ba5da28
[3] 0ba5da34
[4] 0ba5da40
[5] 0ba5da4c
[6] 0ba5da58
[7] 0ba5da64
[8] 0ba5da70
[9] 0ba5da7c
[10] 0ba5da88
...[생략]...
[36] 0ba5dbc0
0:071> !DumpVC /d 1d074248 0ba5da88
Name: System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]]
MethodTable: 1d074248
EEClass: 1d39c52c
Size: 20(0x14) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Core\v4.0_4.0.0.0__b77a5c561934e089\System.Core.dll
Fields:
MT Field Offset Type VT Attr Value Name
0782c9b0 4000e1d 4 System.Int32 1 instance -1 hashCode
0782c9b0 4000e1e 8 System.Int32 1 instance 10 next
078267f8 4000e1f 0 System.__Canon 0 instance 00000000 value
여기까지의 정보를 종합하면 for 문의 첫 번째 루프 상태를 재구성할 수 있습니다.
// 첫 번째 루프에서의 i == 10
for (int i = 10; i >= 0; i = this.m_slots[i].next) // 두 번째 루프에서의 i == this.m_slots[10].next == 10
{
if ((-1 == 0x0dd22b7a) && this.m_comparer.Equals(0, "score"))
{
return true;
}
}
결국, 저렇게 i == 10인 상황이 무한 루프로 빠져 CPU high 현상이 발생합니다.
생각했던 것보다 어렵지 않죠? ^^ C/C++ 시절에 비하면 소스 코드 없이도 이 정도 분석할 수 있으니 엄청 쉬워진 것입니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]