windbg 분석 사례 - ASP.NET 웹 응용 프로그램의 CPU 100% 현상 (3)
예전에도 기록해 둔 사례가 있지만,
windbg 분석 사례 - cpu 100% 현상 (2)
; https://www.sysnet.pe.kr/2/0/1831
windbg 분석 사례 - cpu 100% 현상 (1)
; https://www.sysnet.pe.kr/2/0/1839
개인적으로 피하고 싶은 덤프 분석이 있다면 바로 CPU High 현상입니다. 그래도 다행히 이번 사례는 현장 담당자들의 적절한 조치로 쉽게 분석을 할 수 있었습니다. 어떤 조치였냐면, CPU high 현상을 보고 덤프를 뜬 다음, 잠시 후 다시 덤프를 떠서 스냅 사진을 2장 확보한 것입니다. 사실, 대부분의 일반적인 현장 담당자들은 CPU high가 목격되면 곧바로 iisreset을 해버립니다. 그보다 좀 숙련된 담당자라 해도 덤프 한번 뜨고 iisreset을 해버리는데요, 2개의 덤프를 떴다는 것은 대단한 센스가 아닐 수 없습니다. ^^
CPU high의 대부분의 원인은 특정 코드에 대한 무한 루프 현상입니다. 그런데, 덤프 한 개로는 실 서버에서 운영 중인 수많은 스레드에서 어떤 것이 무한 루프를 돌고 있는지 찾기란 그리 쉽지 않습니다. 다행히, 이번에는 2장의 스냅 샷을 확보했으니, 먼저 첫 번째 덤프로부터
Debug Diagnostic Tool을 이용해 CPU 사용률 Top 5를 다음과 같이 볼 수 있었습니다. (참고로 windbg의 !runaway 명령어로도 스레드의 CPU 사용률을 볼 수 있습니다.)
Top 5 Threads by CPU time
Note - Times include both user mode and kernel mode for each thread
Thread ID: 38 Total CPU Time: 00:13:04.171 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 28 Total CPU Time: 00:10:16.061 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 39 Total CPU Time: 00:07:12.733 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 52 Total CPU Time: 00:00:57.593 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 37 Total CPU Time: 00:00:50.937 Entry Point for Thread: clr!Thread::intermediateThreadProc
위에서 보면, 유독 "분" 단위의 실행 시간을 가진 것이 있습니다. 일단 저것들이 주요 원인일 수 있지만, 두 번째 덤프의 Top 5를 통해 그것을 확정할 수 있습니다.
Top 5 Threads by CPU time
Note - Times include both user mode and kernel mode for each thread
Thread ID: 38 Total CPU Time: 00:13:19.124 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 28 Total CPU Time: 00:10:31.030 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 39 Total CPU Time: 00:07:27.655 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 52 Total CPU Time: 00:00:58.593 Entry Point for Thread: clr!Thread::intermediateThreadProc
Thread ID: 37 Total CPU Time: 00:00:51.437 Entry Point for Thread: clr!Thread::intermediateThreadProc
그 3개의 CPU 사용 시간은 모두 15초, 15초, 15초의 시간을 갖고 있으니 모두 덤프를 뜨는 동안 내내 실행 중이었음을 짐작할 수 있습니다. 자, 그럼 이제 그 시간 동안 CPU를 과점유했으니 그것들의 콜 스택을 봐야 합니다.
Thread 38 - System ID 3288
Entry point clr!Thread::intermediateThreadProc
Create time 2018-07-04 오전 8:59:08
Time spent in user mode 0 Days 00:13:03.515
Time spent in kernel mode 0 Days 00:00:00.656
This thread is not fully resolved and may or may not be a problem. Further analysis of these threads may be required.
.NET Call Stack
System_Core_ni!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+74
System_Web_ni!System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)+c11497
System_Web_ni!System.Web.HttpCookieCollection.Get(System.String)+b6
MyWebApp.Web.CheckCookie()+fc
...[생략]...
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+80f
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+22
System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+51
[[ContextTransitionFrame]]
Thread 28 - System ID 3876
Entry point clr!Thread::intermediateThreadProc
Create time 2018-07-04 오전 8:59:00
Time spent in user mode 0 Days 00:10:14.890
Time spent in kernel mode 0 Days 00:00:01.171
This thread is not fully resolved and may or may not be a problem. Further analysis of these threads may be required.
Thread 39 - System ID 4744
Entry point clr!Thread::intermediateThreadProc
Create time 2018-07-04 오전 8:59:10
Time spent in user mode 0 Days 00:07:11.218
Time spent in kernel mode 0 Days 00:00:01.515
This thread is not fully resolved and may or may not be a problem. Further analysis of these threads may be required.
.NET Call Stack
System_Core_ni!System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)+8c
System_Web_ni!System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)+c11497
System_Web_ni!System.Web.HttpCookieCollection.Get(System.String)+b6
MyWebApp.Web.CheckCookie()+fc
...[생략]...
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+80f
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+22
System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+51
[[ContextTransitionFrame]]
그런데 28번 스레드가 이상합니다. CPU 시간은 분명히 지나 있는데 콜 스택이 없으니 코드를 실행하지도 않은 대기 상태의 스레드 풀의 스레드가 CPU를 점유했다는 이야기가 되기 때문입니다. 사실 이게
Debug Diagnostic Tool 분석의 단점입니다. 좀 더 정확한 분석은, windbg 내에서 직접 !clrstack 명령어로 28번 스레드에 대해 확인하면 정상적인 콜 스택이 보이는 것으로 확인할 수 있습니다.
어쨌든 (windbg로 확인한) 28번을 비롯해 38, 39번 스레드의 경우에는 (운이 좋게도) 문제를 일으킨 상단의 메서드가 동일합니다. 게다가 두 번째 덤프에서도 저 상황은 바뀌지 않았습니다. 아하... 문제가 많이 좁혀졌습니다. 그러니까, 저 HashSet.Contains 메서드에서 무한 루프에 빠져 있는 것입니다.
CPU high 현상의 덤프 중에서 분석이 까다로운 것이 있다면 바로 .NET BCL에서 저렇게 문제가 발생한 경우입니다. 왜냐하면, .NET BCL은 꽤나 많은 최적화가 되어 있고 코딩 방식도 어려운 유형에 속하기 때문에 분석에 그만큼 시간이 걸립니다. 반면 (저를 포함한) 일반 개발자들이 만든 코드는 ^^ 많이 뻔해서 분석이 제법 쉽습니다.
어쨌든 저렇게 콜 스택의 무한 루프 메서드가 .NET BCL의 메서드이니... 숨을 한번 고르고 시작해야 할 것 같습니다.
이제부터는
Debug Diagnostic Tool로는 안 되고 windbg를 직접 사용해야 합니다. 왜 무한 루프에 빠졌는지 분석을 위해 이제 문맥 분석을 해보겠습니다.
0:038> !clrstack
OS Thread Id: 0xcd8 (38)
Child SP IP Call Site
0000000017c1cfe0 000007fef3e68cf4 System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
0000000017c1d050 000007fef39c5d87 System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)
0000000017c1d090 000007fef2d9ffa6 System.Web.HttpCookieCollection.Get(System.String)
...[생략]...
Contains 메서드가 실행 중인 IP 주소를 대상으로 역어셈블을 하니,
0:038> !U /d 000007fef3e68cf4
preJIT generated code
System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
Begin 000007fef3e68c80, size 116
000007fe`f3e68c80 53 push rbx
000007fe`f3e68c81 55 push rbp
000007fe`f3e68c82 56 push rsi
000007fe`f3e68c83 57 push rdi
000007fe`f3e68c84 4154 push r12
000007fe`f3e68c86 4155 push r13
000007fe`f3e68c88 4883ec38 sub rsp,38h
000007fe`f3e68c8c 488bea mov rbp,rdx
000007fe`f3e68c8f 488bd9 mov rbx,rcx
000007fe`f3e68c92 48895c2420 mov qword ptr [rsp+20h],rbx
000007fe`f3e68c97 488b4308 mov rax,qword ptr [rbx+8]
000007fe`f3e68c9b 4885c0 test rax,rax
000007fe`f3e68c9e 0f84df000000 je System_Core_ni+0x2a8d83 (000007fe`f3e68d83)
000007fe`f3e68ca4 488bd5 mov rdx,rbp
000007fe`f3e68ca7 488bcb mov rcx,rbx
000007fe`f3e68caa e841050000 call System_Core_ni+0x2a91f0 (000007fe`f3e691f0) (System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].InternalGetHashCode(System.__Canon), mdToken: 00000000060012c4)
000007fe`f3e68caf 448be8 mov r13d,eax
000007fe`f3e68cb2 4c8b4308 mov r8,qword ptr [rbx+8]
000007fe`f3e68cb6 498b4808 mov rcx,qword ptr [r8+8]
000007fe`f3e68cba 4181fd00000080 cmp r13d,80000000h
000007fe`f3e68cc1 7509 jne System_Core_ni+0x2a8ccc (000007fe`f3e68ccc)
000007fe`f3e68cc3 83f9ff cmp ecx,0FFFFFFFFh
000007fe`f3e68cc6 0f84c4000000 je System_Core_ni+0x2a8d90 (000007fe`f3e68d90)
000007fe`f3e68ccc 418bc5 mov eax,r13d
000007fe`f3e68ccf 99 cdq
000007fe`f3e68cd0 f7f9 idiv eax,ecx
000007fe`f3e68cd2 4863c2 movsxd rax,edx
000007fe`f3e68cd5 483bc1 cmp rax,rcx
000007fe`f3e68cd8 0f83a9000000 jae System_Core_ni+0x2a8d87 (000007fe`f3e68d87)
000007fe`f3e68cde 418b448010 mov eax,dword ptr [r8+rax*4+10h]
000007fe`f3e68ce3 8d78ff lea edi,[rax-1]
000007fe`f3e68ce6 85ff test edi,edi
000007fe`f3e68ce8 0f8c95000000 jl System_Core_ni+0x2a8d83 (000007fe`f3e68d83)
000007fe`f3e68cee 6690 xchg ax,ax
000007fe`f3e68cf0 488b5310 mov rdx,qword ptr [rbx+10h]
>>> 000007fe`f3e68cf4 4863cf movsxd rcx,edi // 이렇게 >>> 표시가 된 코드가 현재 CPU에 의해 실행 중인 지점을 나타냄
000007fe`f3e68cf7 488b4208 mov rax,qword ptr [rdx+8]
000007fe`f3e68cfb 483bc8 cmp rcx,rax
000007fe`f3e68cfe 0f8383000000 jae System_Core_ni+0x2a8d87 (000007fe`f3e68d87)
000007fe`f3e68d04 48c1e104 shl rcx,4
000007fe`f3e68d08 8b440a18 mov eax,dword ptr [rdx+rcx+18h]
...[생략]...
000007fe`f3e68d87 e87c91fbff call System_Core_ni+0x261f08 (000007fe`f3e21f08) (System_Core_ni)
000007fe`f3e68d8c 0f1f4000 nop dword ptr [rax]
000007fe`f3e68d90 e88391fbff call System_Core_ni+0x261f18 (000007fe`f3e21f18) (System_Core_ni)
000007fe`f3e68d95 90 nop
중간에 rcx, rdx 레지스터에 실려온 인자를 각각 rbx, rbp에 보관하고 있으며 이후 바뀌지 않은 것을 볼 수 있습니다. 따라서 (rcx에는 this 포인터 값이고, 첫 번째 인자를 실어서 넘긴) rdx 값을 보관 중인 rbp 값을 보면 HashSet.Contains에 넘어 온 문자열 값을 확인할 수 있습니다.
0:038> !do @rbp
Name: System.String
MethodTable: 000007fef5926508
EEClass: 000007fef5243750
Size: 36(0x24) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: speed
Fields:
MT Field Offset Type VT Attr Value Name
000007fef59292b8 40000aa 8 System.Int32 1 instance 5 m_stringLength
000007fef59277f0 40000ab c System.Char 1 instance 73 m_firstChar
000007fef5926508 40000ac 18 System.String 0 shared static Empty
>> Domain:Value 00000000023db7f0:NotInit 00000000024d4440:NotInit <<
그리고, .NET Reflector를 이용해 HashSet.Contains와 그것을 호출한 HttpCookieCollection.EnsureKeyValidated, HttpCookieCollection.Get 메서드를 확인해 보면 이제 전체적인 스토리가 나옵니다.
// System.Web.HttpCookieCollection
public HttpCookie Get(string name)
{
HttpCookie cookie = (HttpCookie) base.BaseGet(name);
if ((cookie == null) && (this._response != null))
{
cookie = new HttpCookie(name);
this.AddCookie(cookie, true);
this._response.OnCookieAdd(cookie);
}
if (cookie != null)
{
this.EnsureKeyValidated(name, cookie.Value);
}
return cookie;
}
// System.Web.HttpCookieCollection
private void EnsureKeyValidated(string key, string value)
{
if ((this._keysAwaitingValidation != null) && this._keysAwaitingValidation.Contains(key))
{
if (!string.IsNullOrEmpty(value))
{
this._validationCallback(key, value);
}
this._keysAwaitingValidation.Remove(key);
}
}
// System.Collections.Generic.HashSet
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int hashCode = this.InternalGetHashCode(item);
// 아래의 for 루프에서 벗어나지 못하고 무한 실행
for (int i = this.m_buckets[hashCode % this.m_buckets.Length] - 1; i >= 0; i = this.m_slots[i].next)
{
if ((this.m_slots[i].hashCode == hashCode) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
자, 그럼 Contains("speed")로 호출을 했는데, 왜 Contains에서 못 벗어나고 있는지 for 루프의 실행을 재구성해봐야 합니다.
우선, item == "speed" 값에 대한 hashCode를 구해야 합니다. .NET에서 해시 코드 루틴은 .NET Framework 버전마다 달라질 수 있으므로 제 로컬에서 임시 프로젝트 구성 후 실행하게 되면 결과가 달라질 수 있습니다. 따라서 가장 좋은 것은 역시 덤프 파일 내에서 찾아내는 것인데,
0:038> !U /d 000007fef3e68cf4
preJIT generated code
System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
Begin 000007fef3e68c80, size 116
000007fe`f3e68c80 53 push rbx
...[생략]...
000007fe`f3e68caa e841050000 call System_Core_ni+0x2a91f0 (000007fe`f3e691f0) (System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].InternalGetHashCode(System.__Canon), mdToken: 00000000060012c4)
000007fe`f3e68caf 448be8 mov r13d,eax
...[생략]...
InternalGetHashCode 호출에 대한 결과를 r13d 레지스터에 보관하고 있고 이후의 코드를 봐도 변경하지 않고 있습니다. 따라서 다음과 같이 값을 알아낼 수 있습니다.
0:038> ? @r13d
Evaluate expression: 231877498 = 00000000`0dd22b7a
여기까지 구성해 보면, 다음과 같습니다.
Contains("speed");
// System.Collections.Generic.HashSet
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int hashCode = 0x0dd22b7a; // this.InternalGetHashCode(item);
for (int i = this.m_buckets[hashCode % this.m_buckets.Length] - 1; i >= 0; i = this.m_slots[i].next)
{
if ((this.m_slots[i].hashCode == hashCode) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
이제 알아야 할 것은 this.m_buckets.Length입니다. ([참고]
Dumping the contents of a dictionary object using Windbg and SOS.dll) 이건 쉽습니다. ^^ 아까 rcx 레지스터를 rbx에 보관했다고 했는데 그걸 덤프해 보면,
0:038> !do @rbx
Name: System.Collections.Generic.HashSet`1[[System.String, mscorlib]]
MethodTable: 000007fef3bc50c8
EEClass: 000007fef3c22800
Size: 64(0x40) 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
000007fef5929258 40006f5 8 System.Int32[] 0 instance 00000000fff62ba8 m_buckets
000007fef4380b48 40006f6 10 ...non, mscorlib]][] 0 instance 00000000fff62940 m_slots
000007fef59292b8 40006f7 28 System.Int32 1 instance 10 m_count
000007fef59292b8 40006f8 2c System.Int32 1 instance 19 m_lastIndex
000007fef59292b8 40006f9 30 System.Int32 1 instance 2 m_freeList
000007fef5947ab8 40006fa 18 ...Canon, mscorlib]] 0 instance 00000001ffd8a138 m_comparer
000007fef59292b8 40006fb 34 System.Int32 1 instance 28 m_version
000007fef592ec40 40006fc 20 ...SerializationInfo 0 instance 0000000000000000 m_siInfo
0:038> !DumpObj /d 00000000fff62ba8
Name: System.Int32[]
MethodTable: 000007fef5929258
EEClass: 000007fef52fe338
Size: 172(0xac) bytes
Array: Rank 1, Number of elements 37, Type Int32 (Print Array)
Fields:
None
37이라고 구해집니다. 자... 그럼 제법 많이 분석이 되었습니다.
Contains("speed");
// System.Collections.Generic.HashSet
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int hashCode = 0x0dd22b7a; // this.InternalGetHashCode(item);
// 0x0dd22b7a % 37 == 231,877,498 % 37 == 15
for (int i = this.m_buckets[15] - 1; i >= 0; i = this.m_slots[i].next)
{
if ((this.m_slots[i].hashCode == hashCode) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
this.m_buckets[15]의 값은 "!DumpObj /d 00000000fff62ba8" 명령어 대신 "!dumparray"를 통해 배열의 항목들을 덤프할 수 있습니다.
0:038> !DumpArray /d 00000000fff62ba8
Name: System.Int32[]
MethodTable: 000007fef5929258
EEClass: 000007fef52fe338
Size: 172(0xac) bytes
Array: Rank 1, Number of elements 37, Type Int32
Element Methodtable: 000007fef59292b8
[0] 00000000fff62bb8
[1] 00000000fff62bbc
[2] 00000000fff62bc0
[3] 00000000fff62bc4
[4] 00000000fff62bc8
[5] 00000000fff62bcc
[6] 00000000fff62bd0
[7] 00000000fff62bd4
[8] 00000000fff62bd8
[9] 00000000fff62bdc
[10] 00000000fff62be0
[11] 00000000fff62be4
[12] 00000000fff62be8
[13] 00000000fff62bec
[14] 00000000fff62bf0
[15] 00000000fff62bf4
[16] 00000000fff62bf8
[17] 00000000fff62bfc
...[생략]...
[35] 00000000fff62c44
[36] 00000000fff62c48
개별 항목의 값을 덤프하려면 이제 !dumpvc 명령어를 "Element Methodtable"을 함께 지정해 요소의 주소를 넣어주면 됩니다.
0:038> !DumpVC /d 000007fef59292b8 00000000fff62bf4
Name: System.Int32
MethodTable: 000007fef59292b8
EEClass: 000007fef52fe2c8
Size: 24(0x18) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
000007fef59292b8 4000451 0 System.Int32 1 instance 1 m_value
결국 for 루프의 시작 조건은 이렇게 구성됩니다.
Contains("speed");
// System.Collections.Generic.HashSet
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int hashCode = 0x0dd22b7a; // this.InternalGetHashCode(item);
// 0x0dd22b7a % 37 == 231,877,498 % 37 == 15
// this.m_buckets[15] == 1
// for (int i = (1 - 1); i >= 0; i = this.m_slots[i].next)
for (int i = 0; i >= 0; i = this.m_slots[i].next)
{
if ((this.m_slots[i].hashCode == hashCode) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
따라서 i >= 0 인 조건을 만족하므로 일단은 for 루프 내에 진입을 하고 이제 this.m_slots[0] 값을 알아내야 합니다. "!do @rbx"의 출력에서 m_slots의 값을 알고 있으므로 다음과 같이 덤프해 가면서 m_slots[0]의 요소 값도 알아낼 수 있습니다.
0:038> !DumpArray /d 00000000fff62940
Name: System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]][]
MethodTable: 000007fef3ed4200
EEClass: 000007fef3ca7200
Size: 616(0x268) bytes
Array: Rank 1, Number of elements 37, Type VALUETYPE
Element Methodtable: 000007fef3ed4190
[0] 00000000fff62950
[1] 00000000fff62960
[2] 00000000fff62970
[3] 00000000fff62980
...[생략]...
[36] 00000000fff62b90
0:038> !DumpVC /d 000007fef3ed4190 00000000fff62950
Name: System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]]
MethodTable: 000007fef3ed4190
EEClass: 000007fef3c22de0
Size: 32(0x20) 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
000007fef59292b8 4000706 8 System.Int32 1 instance -1 hashCode
000007fef592b758 4000707 0 System.__Canon 0 instance 0000000000000000 value
000007fef59292b8 4000708 c System.Int32 1 instance 0 next
자, 이제 분석이 거의 끝났습니다. 첫 번째 루프는 다음과 같이 실행되고,
Contains("speed");
// System.Collections.Generic.HashSet
[__DynamicallyInvokable]
public bool Contains(T item)
{
if (this.m_buckets != null)
{
int hashCode = 0x0dd22b7a; // this.InternalGetHashCode(item);
for (int i = 0; i >= 0; i = this.m_slots[i].next)
{
// this.m_slots[0].hashCode == -1
if ((this.m_slots[0].hashCode == hashCode) && this.m_comparer.Equals(this.m_slots[i].value, item))
{
return true;
}
}
}
return false;
}
당연히 hashCode가 다르므로 false 조건이 되어 다음번 루프로 넘어가는데 "i = this.m_slots[i].next" 코드가 실행되어 this.m_slots[0].next의 값이 i에 할당됩니다. 그리고 위에서 본대로 m_slots[0].next == 0이므로 i 값은 0이 됩니다.
아하... 그렇군요. 이제 계속해서 0번 m_slots 값에 의해 무한 루프에 빠질 수밖에 없었던 것입니다.
일단, 분석은 끝났고 그렇다면 저런 현상이 발생할 수 있는 상황을 찾아야 합니다. m_slots[0]의 hashCode가 -1인 것으로 보아 삭제 처리된 슬롯으로 보입니다. HashSet 타입의 코드를 보면 삭제 처리된 경우 next 값 역시 -1이 되거나 아니면 자기 자신이 아닌 다른 슬롯의 인덱스 값을 가지고 있어야 합니다.
사실, 여전히 왜 저런 결과가 나왔는지 알 수 없습니다. 그래도 나름 분석한 결과가 지난번의 글입니다.
ASP.NET - HttpCookieCollection을 다중 스레드에서 사용할 경우 무한 루프 현상
; https://www.sysnet.pe.kr/2/0/11587
실제로 다중 스레드에 의한 원인인지는, 해당 웹 응용 프로그램을 개발한 측의 소스 코드를 면밀히 검토해 보는 수밖에는 없습니다. 물론, .NET Reflector 등으로 덤프 파일의 모든 사용자 DLL을 역어셈블할 수는 있겠지만 그래도 원인을 찾으려면 지루한 작업이 될 수밖에는 없습니다. 반면 내부 개발자가 검토하면 좀 더 수월하게 결과를 낼 수 있을 것이고.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]