성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] Reordering on an Alpha processor ;...
[정성태] 공유 감사합니다. ^^ 참고로, WPF에서 WindowsF...
[Tom Lee] 답변 감사합니다. 나름의 해결책 연구해보고 여기에도 공유해봅니다...
[정성태] 아래의 글을 보면, MoveWindow 하면 될 듯한데요. ^^...
[Tom Lee] 안녕하세요 올려주신 글 참고하여 WPF 어플리케이션 안에 Uni...
[정성태] A graphical depiction of the steps ...
[정성태] 질문을 주셔서 출판사 측에 문의를 했습니다. 약 한 달 정도 후...
[Thorondor
] @정성태 개인 블로그인데도 거의 커뮤니티 급 인 것 같아요. 요...
[정성태] Roll A Lisp In C - Reading ; https...
[정성태] Java - How to use the Foreign Funct...
글쓰기
제목
이름
암호
전자우편
HTML
홈페이지
유형
제니퍼 .NET
닷넷
COM 개체 관련
스크립트
VC++
VS.NET IDE
Windows
Team Foundation Server
디버깅 기술
오류 유형
개발 환경 구성
웹
기타
Linux
Java
DDK
Math
Phone
Graphics
사물인터넷
부모글 보이기/감추기
내용
<div style='display: inline'> <h1 style='font-family: Malgun Gothic, Consolas; font-size: 20pt; color: #006699; text-align: center; font-weight: bold'>windbg 분석 사례 - ASP.NET 웹 응용 프로그램의 CPU 100% 현상 (3)</h1> <p> 예전에도 기록해 둔 사례가 있지만,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > windbg 분석 사례 - cpu 100% 현상 (2) ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/1831'>http://www.sysnet.pe.kr/2/0/1831</a> windbg 분석 사례 - cpu 100% 현상 (1) ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/1839'>http://www.sysnet.pe.kr/2/0/1839</a> </pre> <br /> 개인적으로 피하고 싶은 덤프 분석이 있다면 바로 CPU High 현상입니다. 그래도 다행히 이번 사례는 현장 담당자들의 적절한 조치로 쉽게 분석을 할 수 있었습니다. 어떤 조치였냐면, CPU high 현상을 보고 덤프를 뜬 다음, 잠시 후 다시 덤프를 떠서 스냅 사진을 2장 확보한 것입니다. 사실, 대부분의 일반적인 현장 담당자들은 CPU high가 목격되면 곧바로 iisreset을 해버립니다. 그보다 좀 숙련된 담당자라 해도 덤프 한번 뜨고 iisreset을 해버리는데요, 2개의 덤프를 떴다는 것은 대단한 센스가 아닐 수 없습니다. ^^<br /> <br /> <hr style='width: 50%' /><br /> <br /> CPU high의 대부분의 원인은 특정 코드에 대한 무한 루프 현상입니다. 그런데, 덤프 한 개로는 실 서버에서 운영 중인 수많은 스레드에서 어떤 것이 무한 루프를 돌고 있는지 찾기란 그리 쉽지 않습니다. 다행히, 이번에는 2장의 스냅 샷을 확보했으니, 먼저 첫 번째 덤프로부터 <a target='tab' href='https://www.microsoft.com/en-us/download/details.aspx?id=49924'>Debug Diagnostic Tool</a>을 이용해 CPU 사용률 Top 5를 다음과 같이 볼 수 있었습니다. (참고로 windbg의 !runaway 명령어로도 스레드의 CPU 사용률을 볼 수 있습니다.)<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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:<span style='color: blue; font-weight: bold'>13:04</span>.171 Entry Point for Thread: clr!Thread::intermediateThreadProc Thread ID: 28 Total CPU Time: 00:<span style='color: blue; font-weight: bold'>10:16</span>.061 Entry Point for Thread: clr!Thread::intermediateThreadProc Thread ID: 39 Total CPU Time: 00:<span style='color: blue; font-weight: bold'>07:12</span>.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 </pre> <br /> 위에서 보면, 유독 "분" 단위의 실행 시간을 가진 것이 있습니다. 일단 저것들이 주요 원인일 수 있지만, 두 번째 덤프의 Top 5를 통해 그것을 확정할 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Top 5 Threads by CPU time Note - Times include both user mode and kernel mode for each thread <span style='color: blue; font-weight: bold'>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 </span> 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 </pre> <br /> 그 3개의 CPU 사용 시간은 모두 15초, 15초, 15초의 시간을 갖고 있으니 모두 덤프를 뜨는 동안 내내 실행 중이었음을 짐작할 수 있습니다. 자, 그럼 이제 그 시간 동안 CPU를 과점유했으니 그것들의 콜 스택을 봐야 합니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > <span style='color: blue; font-weight: bold'>Thread 38</span> - 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 <span style='color: blue; font-weight: bold'>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 </span>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]] </pre> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > <span style='color: blue; font-weight: bold'>Thread 28</span> - 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. </pre> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > <span style='color: blue; font-weight: bold'>Thread 39</span> - 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 <span style='color: blue; font-weight: bold'>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 </span> 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]] </pre> <br /> 그런데 28번 스레드가 이상합니다. CPU 시간은 분명히 지나 있는데 콜 스택이 없으니 코드를 실행하지도 않은 대기 상태의 스레드 풀의 스레드가 CPU를 점유했다는 이야기가 되기 때문입니다. 사실 이게 <a target='tab' href='https://www.microsoft.com/en-us/download/details.aspx?id=49924'>Debug Diagnostic Tool</a> 분석의 단점입니다. 좀 더 정확한 분석은, windbg 내에서 직접 !clrstack 명령어로 28번 스레드에 대해 확인하면 정상적인 콜 스택이 보이는 것으로 확인할 수 있습니다.<br /> <br /> 어쨌든 (windbg로 확인한) 28번을 비롯해 38, 39번 스레드의 경우에는 (운이 좋게도) 문제를 일으킨 상단의 메서드가 동일합니다. 게다가 두 번째 덤프에서도 저 상황은 바뀌지 않았습니다. 아하... 문제가 많이 좁혀졌습니다. 그러니까, 저 HashSet.Contains 메서드에서 무한 루프에 빠져 있는 것입니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> CPU high 현상의 덤프 중에서 분석이 까다로운 것이 있다면 바로 .NET BCL에서 저렇게 문제가 발생한 경우입니다. 왜냐하면, .NET BCL은 꽤나 많은 최적화가 되어 있고 코딩 방식도 어려운 유형에 속하기 때문에 분석에 그만큼 시간이 걸립니다. 반면 (저를 포함한) 일반 개발자들이 만든 코드는 ^^ 많이 뻔해서 분석이 제법 쉽습니다.<br /> <br /> 어쨌든 저렇게 콜 스택의 무한 루프 메서드가 .NET BCL의 메서드이니... 숨을 한번 고르고 시작해야 할 것 같습니다.<br /> <br /> 이제부터는 <a target='tab' href='https://www.microsoft.com/en-us/download/details.aspx?id=49924'>Debug Diagnostic Tool</a>로는 안 되고 windbg를 직접 사용해야 합니다. 왜 무한 루프에 빠졌는지 분석을 위해 이제 문맥 분석을 해보겠습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!clrstack</span> OS Thread Id: 0xcd8 (38) Child SP IP Call Site 0000000017c1cfe0 <span style='color: blue; font-weight: bold'>000007fef3e68cf4</span> 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) ...[생략]... </pre> <br /> Contains 메서드가 실행 중인 IP 주소를 대상으로 역어셈블을 하니,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!U /d 000007fef3e68cf4</span> 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 <span style='color: blue; font-weight: bold'>000007fe`f3e68c8c 488bea mov rbp,rdx 000007fe`f3e68c8f 488bd9 mov rbx,rcx</span> 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] <span style='color: blue; font-weight: bold'>>>> 000007fe`f3e68cf4 4863cf movsxd rcx,edi</span> // 이렇게 >>> 표시가 된 코드가 현재 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 </pre> <br /> 중간에 rcx, rdx 레지스터에 실려온 인자를 각각 rbx, rbp에 보관하고 있으며 이후 바뀌지 않은 것을 볼 수 있습니다. 따라서 (rcx에는 this 포인터 값이고, 첫 번째 인자를 실어서 넘긴) rdx 값을 보관 중인 rbp 값을 보면 HashSet.Contains에 넘어 온 문자열 값을 확인할 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!do @rbp</span> 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 << </pre> <br /> 그리고, .NET Reflector를 이용해 HashSet.Contains와 그것을 호출한 HttpCookieCollection.EnsureKeyValidated, HttpCookieCollection.Get 메서드를 확인해 보면 이제 전체적인 스토리가 나옵니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > // 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) { <span style='color: blue; font-weight: bold'>this.EnsureKeyValidated(name, cookie.Value);</span> } return cookie; } // System.Web.HttpCookieCollection private void EnsureKeyValidated(string key, string value) { if ((this._keysAwaitingValidation != null) && <span style='color: blue; font-weight: bold'>this._keysAwaitingValidation.Contains(key)</span>) { if (!string.IsNullOrEmpty(value)) { this._validationCallback(key, value); } this._keysAwaitingValidation.Remove(key); } } // System.Collections.Generic.HashSet<T> [__DynamicallyInvokable] public bool Contains(T item) { if (this.m_buckets != null) { int hashCode = this.InternalGetHashCode(item); <span style='color: blue; font-weight: bold'>// 아래의 for 루프에서 벗어나지 못하고 무한 실행</span> <span style='color: blue; font-weight: bold'>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; } }</span> } return false; } </pre> <br /> 자, 그럼 Contains("speed")로 호출을 했는데, 왜 Contains에서 못 벗어나고 있는지 for 루프의 실행을 재구성해봐야 합니다. <br /> <br /> 우선, item == "speed" 값에 대한 hashCode를 구해야 합니다. .NET에서 해시 코드 루틴은 .NET Framework 버전마다 달라질 수 있으므로 제 로컬에서 임시 프로젝트 구성 후 실행하게 되면 결과가 달라질 수 있습니다. 따라서 가장 좋은 것은 역시 덤프 파일 내에서 찾아내는 것인데,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!U /d 000007fef3e68cf4</span> 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]].<span style='color: blue; font-weight: bold'>InternalGetHashCode</span>(System.__Canon), mdToken: 00000000060012c4) 000007fe`f3e68caf 448be8 <span style='color: blue; font-weight: bold'>mov r13d,eax</span> ...[생략]... </pre> <br /> InternalGetHashCode 호출에 대한 결과를 r13d 레지스터에 보관하고 있고 이후의 코드를 봐도 변경하지 않고 있습니다. 따라서 다음과 같이 값을 알아낼 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>? @r13d</span> Evaluate expression: 231877498 = 00000000`0dd22b7a </pre> <br /> 여기까지 구성해 보면, 다음과 같습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Contains("speed"); // System.Collections.Generic.HashSet<T> [__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; } </pre> <br /> 이제 알아야 할 것은 this.m_buckets.Length입니다. ([참고] <a target='tab' href='https://blogs.msdn.microsoft.com/rihamselim/2013/08/16/dumping-the-contents-of-a-dictionary-object-using-windbg-and-sos-dll/'>Dumping the contents of a dictionary object using Windbg and SOS.dll</a>) 이건 쉽습니다. ^^ 아까 rcx 레지스터를 rbx에 보관했다고 했는데 그걸 덤프해 보면,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!do @rbx</span> 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 <span style='color: blue; font-weight: bold'>000007fef5929258 40006f5 8 System.Int32[] 0 instance 00000000fff62ba8 m_buckets</span> 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> <span style='color: blue; font-weight: bold'>!DumpObj /d 00000000fff62ba8</span> Name: System.Int32[] MethodTable: 000007fef5929258 EEClass: 000007fef52fe338 Size: 172(0xac) bytes Array: Rank 1, <span style='color: blue; font-weight: bold'>Number of elements 37</span>, Type Int32 (Print Array) Fields: None </pre> <br /> 37이라고 구해집니다. 자... 그럼 제법 많이 분석이 되었습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Contains("speed"); // System.Collections.Generic.HashSet<T> [__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 (<span style='color: blue; font-weight: bold'>int i = this.m_buckets[15] - 1</span>; 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; } </pre> <br /> this.m_buckets[15]의 값은 "!DumpObj /d 00000000fff62ba8" 명령어 대신 "!dumparray"를 통해 배열의 항목들을 덤프할 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!DumpArray /d 00000000fff62ba8</span> Name: System.Int32[] MethodTable: 000007fef5929258 EEClass: 000007fef52fe338 Size: 172(0xac) bytes Array: Rank 1, Number of elements 37, Type Int32 <span style='color: blue; font-weight: bold'>Element Methodtable: 000007fef59292b8</span> [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 <span style='color: blue; font-weight: bold'>[15] 00000000fff62bf4</span> [16] 00000000fff62bf8 [17] 00000000fff62bfc ...[생략]... [35] 00000000fff62c44 [36] 00000000fff62c48 </pre> <br /> <a name="dumpvc"></a> 개별 항목의 값을 덤프하려면 이제 !dumpvc 명령어를 "Element Methodtable"을 함께 지정해 요소의 주소를 넣어주면 됩니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!DumpVC /d 000007fef59292b8 00000000fff62bf4</span> 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 <span style='color: blue; font-weight: bold'>1 m_value</span> </pre> <br /> 결국 for 루프의 시작 조건은 이렇게 구성됩니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Contains("speed"); // System.Collections.Generic.HashSet<T> [__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; } </pre> <br /> 따라서 i >= 0 인 조건을 만족하므로 일단은 for 루프 내에 진입을 하고 이제 this.m_slots[0] 값을 알아내야 합니다. "!do @rbx"의 출력에서 m_slots의 값을 알고 있으므로 다음과 같이 덤프해 가면서 m_slots[0]의 요소 값도 알아낼 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:038> <span style='color: blue; font-weight: bold'>!DumpArray /d 00000000fff62940</span> 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: <span style='color: blue; font-weight: bold'>000007fef3ed4190</span> [0] <span style='color: blue; font-weight: bold'>00000000fff62950</span> [1] 00000000fff62960 [2] 00000000fff62970 [3] 00000000fff62980 ...[생략]... [36] 00000000fff62b90 0:038> <span style='color: blue; font-weight: bold'>!DumpVC /d 000007fef3ed4190 00000000fff62950</span> 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 <span style='color: blue; font-weight: bold'>-1 hashCode</span> 000007fef592b758 4000707 0 System.__Canon 0 instance <span style='color: blue; font-weight: bold'>0000000000000000 value</span> 000007fef59292b8 4000708 c System.Int32 1 instance <span style='color: blue; font-weight: bold'>0 next</span> </pre> <br /> 자, 이제 분석이 거의 끝났습니다. 첫 번째 루프는 다음과 같이 실행되고,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Contains("speed"); // System.Collections.Generic.HashSet<T> [__DynamicallyInvokable] public bool Contains(T item) { if (this.m_buckets != null) { int hashCode = 0x0dd22b7a; // this.InternalGetHashCode(item); for (int i = 0; i >= 0; <span style='color: blue; font-weight: bold'>i = this.m_slots[i].next</span>) { // this.m_slots[0].hashCode == -1 if (<span style='color: blue; font-weight: bold'>(this.m_slots[0].hashCode == hashCode)</span> && this.m_comparer.Equals(this.m_slots[i].value, item)) { return true; } } } return false; } </pre> <br /> 당연히 hashCode가 다르므로 false 조건이 되어 다음번 루프로 넘어가는데 "i = this.m_slots[i].next" 코드가 실행되어 this.m_slots[0].next의 값이 i에 할당됩니다. 그리고 위에서 본대로 m_slots[0].next == 0이므로 i 값은 0이 됩니다.<br /> <br /> 아하... 그렇군요. 이제 계속해서 0번 m_slots 값에 의해 무한 루프에 빠질 수밖에 없었던 것입니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 일단, 분석은 끝났고 그렇다면 저런 현상이 발생할 수 있는 상황을 찾아야 합니다. m_slots[0]의 hashCode가 -1인 것으로 보아 삭제 처리된 슬롯으로 보입니다. HashSet 타입의 코드를 보면 삭제 처리된 경우 next 값 역시 -1이 되거나 아니면 자기 자신이 아닌 다른 슬롯의 인덱스 값을 가지고 있어야 합니다.<br /> <br /> 사실, 여전히 왜 저런 결과가 나왔는지 알 수 없습니다. 그래도 나름 분석한 결과가 지난번의 글입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > ASP.NET - HttpCookieCollection을 다중 스레드에서 사용할 경우 무한 루프 현상 ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/11587'>http://www.sysnet.pe.kr/2/0/11587</a> </pre> <br /> 실제로 다중 스레드에 의한 원인인지는, 해당 웹 응용 프로그램을 개발한 측의 소스 코드를 면밀히 검토해 보는 수밖에는 없습니다. 물론, .NET Reflector 등으로 덤프 파일의 모든 사용자 DLL을 역어셈블할 수는 있겠지만 그래도 원인을 찾으려면 지루한 작업이 될 수밖에는 없습니다. 반면 내부 개발자가 검토하면 좀 더 수월하게 결과를 낼 수 있을 것이고.<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
1248
(왼쪽의 숫자를 입력해야 합니다.)