Microsoft MVP성태의 닷넷 이야기
글쓴 사람
홈페이지
첨부 파일
 

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을 역어셈블할 수는 있겠지만 그래도 원인을 찾으려면 지루한 작업이 될 수밖에는 없습니다. 반면 내부 개발자가 검토하면 좀 더 수월하게 결과를 낼 수 있을 것이고.




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]

[연관 글]





[최초 등록일: ]
[최종 수정일: 12/19/2019 ]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer@outlook.com

비밀번호

댓글 쓴 사람
 




... 16  17  18  19  20  21  22  [23]  24  25  26  27  28  29  30  ...
NoWriterDateCnt.TitleFile(s)
11653정성태8/18/20181702사물인터넷: 26. 입력 전압에 따른 LED의 전압/저항 변화파일 다운로드1
11652정성태9/11/20181618사물인터넷: 25. 컬렉터 9V, 베이스에 5V와 3.3V 전압으로 테스트하는 C1815 트랜지스터파일 다운로드1
11651정성태9/4/20183129사물인터넷: 24. 9V 전압에서 테스트하는 C1815 트랜지스터파일 다운로드3
11650정성태8/18/20181731사물인터넷: 23. 가변저항으로 분압파일 다운로드1
11649정성태8/14/20181842사물인터넷: 22. 저항에 따른 전류 테스트파일 다운로드1
11648정성태10/17/20182531사물인터넷: 21. 퓨즈를 이용한 회로 보호파일 다운로드3
11647정성태8/8/20181924오류 유형: 476. 음수의 음수는 여전히 음수가 되는 수(절대값이 음수인 수)
11646정성태8/8/20181690오류 유형: 475. gacutil.exe 실행 시 "Failure initializing gacutil" 오류 발생
11645정성태8/8/20181989오류 유형: 474. 닷넷 COM+ - Failed to load the runtime. [1]
11644정성태8/8/20182587디버깅 기술: 118. windbg - 닷넷 개발자를 위한 MEX Debugging Extension 소개
11643정성태8/12/20182767사물인터넷: 20. 아두이노 레오나르도 R3 호환 보드의 3.3v 핀의 LED 전압/전류 테스트 [1]파일 다운로드1
11642정성태8/3/20182664Graphics: 20. Unity - LightMode의 ForwardBase에 따른 _WorldSpaceLightPos0 값 변화
11641정성태8/3/20183878Graphics: 19. Unity로 실습하는 Shader (10) - 빌보드 구현파일 다운로드1
11640정성태8/3/20182883Graphics: 18. Unity - World matrix(unity_ObjectToWorld)로부터 Position, Rotation, Scale 값을 복원하는 방법파일 다운로드1
11639정성태8/2/20182295디버깅 기술: 117. windbg - 덤프 파일로부터 추출한 DLL을 참조하는 방법
11638정성태8/2/20181849오류 유형: 473. windbg - 덤프 파일로부터 추출한 DLL 참조 시 "Resolved file has a bad image, no metadata, or is otherwise inaccessible." 빌드 오류
11637정성태8/1/20182553Graphics: 17. Unity - World matrix(unity_ObjectToWorld)로부터 TRS(이동/회전/크기) 행렬로 복원하는 방법파일 다운로드1
11636정성태8/1/20184170Graphics: 16. 3D 공간에서 두 점이 이루는 각도 구하기파일 다운로드1
11635정성태8/1/20182124오류 유형: 472. C# 컴파일 오류 - Your project is not referencing the ".NETFramework,Version=v3.5" framework.
11634정성태8/1/20182011.NET Framework: 790. .NET Thread 상태가 Cooperative일 때 GC hang 현상 재현 방법파일 다운로드1
11633정성태7/29/20183595Graphics: 15. Unity - shader의 World matrix(unity_ObjectToWorld)를 수작업으로 구성 [1]
11632정성태7/28/20186192Graphics: 14. C# - Unity에서 캐릭터가 바라보는 방향을 기준으로 카메라의 위치 이동 및 회전하는 방법
11631정성태7/27/20184768Graphics: 13. Unity로 실습하는 Shader (9) - 투명 배경이 있는 텍스처 입히기
11630정성태2/11/20202664개발 환경 구성: 391. (GitHub 등과 직접 연동해) 소스 코드 디버깅을 쉽게 해 주는 SourceLink [2]
11629정성태7/26/20182077.NET Framework: 789. C# 컴파일 옵션 - Check for arithmetic overflow/underflow [1]
11628정성태7/26/20183453Graphics: 12. Unity로 실습하는 Shader (8) - 다중 패스(Multi-Pass Shader)
... 16  17  18  19  20  21  22  [23]  24  25  26  27  28  29  30  ...