성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] Java - How to use the Foreign Funct...
[정성태] 제가 큰 실수를 했군요. ^^; Delegate를 통한 Bein...
[정성태] Working with Rust Libraries from C#...
[정성태] Detecting blocking calls using asyn...
[정성태] 아쉽게도, 커뮤니티는 아니고 개인 블로그입니다. ^^
[정성태] 질문이 잘 이해가 안 됩니다. 우선, 해당 소스코드에서 ILis...
[양승조
] var대신 dinamic으로 선언해서 해결은 했습니다. 맞는 해...
[양승조
] 또 막혔습니다. ㅠㅠ var list = props[i].Ge...
[양승조
] 아. 감사합니다. 어제는 안됐던것 같은데....정신을 차려야겠네...
[정성태] "props[i].GetValue(props[i])" 코드에서 ...
글쓰기
제목
이름
암호
전자우편
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 분석 사례 - cpu 100% 현상 (2)</h1> <p> CPU 100% 현상이 연 이어 두번 나오는 군요.<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% 현상 (1) ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/1831'>http://www.sysnet.pe.kr/2/0/1831</a> </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;' > 0:000> <span style='color: blue; font-weight: bold'>!runaway</span> User Mode Time Thread Time 4:67c 1 days 13:50:08.500 5:6b0 0 days 0:00:15.078 8:fd14 0 days 0:00:03.078 ...[생략]... 6:6bc 0 days 0:00:00.000 1:644 0 days 0:00:00.000 </pre> <br /> 4번 스레드로 문맥 전환하고,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:000> <span style='color: blue; font-weight: bold'>~4s</span> *** WARNING: Unable to verify checksum for System.ni.dll clr!ThreadNative::SpinWait+0x25: 000007fe`f8f38fa5 4c8d25d4ffffff lea r12,[clr!ThreadNative::SpinWait (000007fe`f8f38f80)] </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;' > 0:004> <span style='color: blue; font-weight: bold'>!clrstack</span> OS Thread Id: 0x67c (4) Child SP IP Call Site 000000001a88f538 000007fef8f38fa5 [GCFrame: 000000001a88f538] 000000001a88f920 000007fef8f38fa5 [DebuggerU2MCatchHandlerFrame: 000000001a88f920] </pre> <br /> 일단 포기하고, dumpstack으로 우회합니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:004> <span style='color: blue; font-weight: bold'>!dumpstack</span> OS Thread Id: 0x67c (4) Current frame: clr!ThreadNative::SpinWait+0x25 Child-SP RetAddr Caller, Callee 000000001a88e740 000007fef9211c50 clr!Thread::WaitSuspendEvents+0x11, calling clr!Thread::WaitSuspendEventsHelper 000000001a88e770 000007fef8f38f80 000007fef8f38f80 (stub for System.Threading.Thread.SpinWaitInternal(Int32)) 000000001a88e7e0 000007fef8eabcee clr!Thread::RedirectedHandledJITCase+0x173, calling ntdll!RtlRestoreContext 000000001a88e800 000007fef8d63705 clr!ExternalMethodFixupAsm+0x85, calling clr!ExternalMethodFixupWorker 000000001a88e890 000007fef8f5ef1e clr!RedirectedHandledJITCaseForDbgThreadControl_Stub+0x2e, calling clr!Thread::RedirectedHandledJITCaseForDbgThreadControl 000000001a88e8d0 000007fef6e389ac (MethodDesc 000007fef6c59348 +0xdc System.Net.Sockets.Socket.Dispose(Boolean)), calling 000007fef8f38f80 (stub for System.Threading.Thread.SpinWaitInternal(Int32)) 000000001a88e9b0 000007fef6e388a8 (MethodDesc 000007fef6c59360 +0x18 System.Net.Sockets.Socket.Dispose()) 000000001a88e9e0 000007fef7372240 (MethodDesc 000007fef6cb7518 +0x40 System.Net.PooledStream.Close(Int32)), calling 000007ff0005da00 000000001a88ea20 000007fef73d971f (MethodDesc 000007fef6cb71c8 +0x9f System.Net.Connection.HandleError(Boolean, Boolean, System.Net.WebExceptionStatus, System.Net.ConnectionReturnResult ByRef)), calling 000007ff001b52c0 000000001a88ea90 000007fef6e686f2 (MethodDesc 000007fef6cb70a8 +0x212 System.Net.Connection.CompleteStartConnection(Boolean, System.Net.HttpWebRequest)), calling 000007ff001b4e60 000000001a88eaa0 000007fef7c9c001 (MethodDesc 000007fef7975da8 +0x51 System.Collections.ArrayList.set_Capacity(Int32)), calling clr!JIT_WriteBarrier_Fast 000000001a88eab0 000007fef7c9716a (MethodDesc 000007fef7975df8 +0x2a System.Collections.ArrayList.Add(System.Object)), calling clr!JIT_Stelem_Ref 000000001a88eb30 000007fef6e6e90f (MethodDesc 000007fef6cb7088 +0x4f System.Net.Connection.CompleteStartRequest(Boolean, System.Net.HttpWebRequest, System.Net.TriState)), calling 000007ff001b4920 000000001a88eb50 000007fef6e682f8 (MethodDesc 000007fef6c5b208 +0x218 System.Net.Connection..ctor(System.Net.ConnectionGroup)), calling (MethodDesc 000007fef6cb6d88 +0 System.Net.ConnectionGroup.Associate(System.Net.Connection)) 000000001a88eb90 000007fef6e6e250 (MethodDesc 000007fef6c5b240 +0x420 System.Net.Connection.SubmitRequest(System.Net.HttpWebRequest, Boolean)), calling 000007ff001b4840 000000001a88ec20 000007fef6e6d85d (MethodDesc 000007fef6cb6710 +0x10d System.Net.ServicePoint.SubmitRequest(System.Net.HttpWebRequest, System.String)), calling 000007ff001b3ce0 000000001a88ec90 000007fef6e6cd5c (MethodDesc 000007fef6c57320 +0x31c System.Net.HttpWebRequest.SubmitRequest(System.Net.ServicePoint)), calling (MethodDesc 000007fef6cb6710 +0 System.Net.ServicePoint.SubmitRequest(System.Net.HttpWebRequest, System.String)) 000000001a88ecc0 000007fef72f8702 (MethodDesc 000007fef6c57310 +0x12 System.Net.HttpWebRequest.BeginSubmitRequest()), calling 000007ff001b29a0 000000001a88ecf0 000007fef72fd19c (MethodDesc 000007fef6c56d48 +0x43c System.Net.HttpWebRequest.BeginGetResponse(System.AsyncCallback, System.Object)), calling 000007ff001b28c0 000000001a88ed60 000007fef6e2579e (MethodDesc 000007fef6c52150 +0x12e System.Uri.GetComponentsHelper(System.UriComponents, System.UriFormat)), calling (MethodDesc 000007fef6c51698 +0 System.Uri.EnsureHostString(Boolean)) 000000001a88edd0 000007fef72e9048 (MethodDesc 000007fef6caf818 +0xd8 System.Net.WebClient.DownloadBits(System.Net.WebRequest, System.IO.Stream, System.Net.CompletionDelegate, System.ComponentModel.AsyncOperation)) 000000001a88ede0 000007ff0016236f (MethodDesc 000007ff00046bb0 +0x12f System.Net.WebClient.GetWebRequest(System.Uri)) 000000001a88ee00 000007fef7ca1ebe (MethodDesc 000007fef796c928 +0x1e System.MulticastDelegate.CtorClosed(System.Object, IntPtr)), calling clr!JIT_WriteBarrier_Fast 000000001a88ee40 000007fef72ecd70 (MethodDesc 000007fef6cafaa0 +0x160 System.Net.WebClient.DownloadStringAsync(System.Uri, System.Object)), calling 000007ff001b1ac0 000000001a88eec0 000007ff00161e5a (MethodDesc 000007ff00045f38 +0x28a MyTestApp.Call(Int32)), calling 000007ff001b0da0 000000001a88ef40 000007fef7c9d207 (MethodDesc 000007fef7977388 +0x17 System.Collections.Generic.List`1+Enumerator[[System.__Canon, mscorlib]]..ctor(System.Collections.Generic.List`1<System.__Canon>)), calling clr!JIT_CheckedWriteBarrier 000000001a88ef80 000007ff00160560 (MethodDesc 000007ff00045338 +0x110 MyTestApp.ServiceMain(System.Object)), calling (MethodDesc 000007ff00045f38 +0 MyTestApp.Call(Int32)) ...[생략]... 000000001a88fca0 000007fef8f2c71f clr!Thread::intermediateThreadProc+0x66, calling clr!_chkstk 000000001a88fce0 0000000076d559ed kernel32!BaseThreadInitThunk+0xd 000000001a88fd10 0000000076f8ba01 ntdll!RtlUserThreadStart+0x1d </pre> <br /> 그런데, 재미있군요. 실행된 프로세스에 직접 attach 해보니 다음과 같이 !clrstack이 잘 나옵니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:004> <span style='color: blue; font-weight: bold'>!clrstack</span> OS Thread Id: 0x67c (4) Child SP IP Call Site 000000001a88e8e0 000007fef6e389c6 System.Net.Sockets.Socket.Dispose(Boolean) 000000001a88e9c0 000007fef6e388a8 System.Net.Sockets.Socket.Dispose() 000000001a88e9f0 000007fef7372240 System.Net.PooledStream.Close(Int32) 000000001a88ea30 000007fef73d971f System.Net.Connection.HandleError(Boolean, Boolean, System.Net.WebExceptionStatus, System.Net.ConnectionReturnResult ByRef) 000000001a88eaa0 000007fef6e686f2 System.Net.Connection.CompleteStartConnection(Boolean, System.Net.HttpWebRequest) 000000001a88eb40 000007fef6e6e90f System.Net.Connection.CompleteStartRequest(Boolean, System.Net.HttpWebRequest, System.Net.TriState) 000000001a88eba0 000007fef6e6e250 System.Net.Connection.SubmitRequest(System.Net.HttpWebRequest, Boolean) 000000001a88ec30 000007fef6e6d85d System.Net.ServicePoint.SubmitRequest(System.Net.HttpWebRequest, System.String) 000000001a88eca0 000007fef6e6cd5c System.Net.HttpWebRequest.SubmitRequest(System.Net.ServicePoint) 000000001a88ed00 000007fef72fd19c System.Net.HttpWebRequest.BeginGetResponse(System.AsyncCallback, System.Object) 000000001a88ede0 000007fef72e9048 System.Net.WebClient.DownloadBits(System.Net.WebRequest, System.IO.Stream, System.Net.CompletionDelegate, System.ComponentModel.AsyncOperation) 000000001a88ee50 000007fef72ecd70 System.Net.WebClient.DownloadStringAsync(System.Uri, System.Object) 000000001a88eed0 000007ff00161e5a TestApp.Call(Int32)*** WARNING: Unable to verify checksum for d:\TestService.exe [d:\TestService\TestApp.cs @ 86] 000000001a88ef90 000007ff00160560 TestApp.ServiceMain(System.Object) [d:\TestService\PreloadService.cs @ 199] 000000001a88f020 000007fef7c6169c System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)*** WARNING: Unable to verify checksum for C:\Windows\assembly\NativeImages_v4.0.30319_64\mscorlib\7f2c596fb4811af2d6fc7a5132c75d10\mscorlib.ni.dll 000000001a88f080 000007fef7c615ab System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 000000001a88f0d0 000007fef83974ad System.Threading.ThreadHelper.ThreadStart(System.Object) 000000001a88f538 000007fef8d9c9e4 [GCFrame: 000000001a88f538] 000000001a88f920 000007fef8d9c9e4 [DebuggerU2MCatchHandlerFrame: 000000001a88f920] </pre> <br /> 이상하군요.Socket.Dispose(Boolean) 메서드에서 CPU 100% 현상이 발생하다니... 제가 뭔가 잘못한 걸까요? 일단 CPU 100% 현상의 무한 루프에 대한 시작/끝 점을 알기 위해 기계어로 덤프한 후 예전의 글에서 설명했던 것처럼 따라가 보니 다음의 구간을 찾을 수 있었습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:004> !u 000007fef6e389c6 preJIT generated code System.Net.Sockets.Socket.Dispose(Boolean) Begin 000007fef6e388d0, size 48d. Cold region begin 000007fef75dc460, size a1 Hot region: 000007fe`f6e388d0 53 push rbx 000007fe`f6e388d1 55 push rbp 000007fe`f6e388d2 56 push rsi 000007fe`f6e388d3 57 push rdi ...[생략]... 000007fe`f6e38999 e82260faff call System_ni+0x1ee9c0 (000007fe`f6dde9c0) (System.Net.Logging.Enter(System.Diagnostics.TraceSource, System.Object, System.String, System.String), mdToken: 0000000006002321) 000007fe`f6e3899e 6690 xchg ax,ax 000007fe`f6e389a0 eb0e jmp System_ni+0x2489b0 (000007fe`f6e389b0) <span style='color: blue; font-weight: bold'>//------------------ 반복 시작 ------------------------------ 000007fe`f6e389a2 b901000000 mov ecx,1 000007fe`f6e389a7 e80cb1f8ff call System_ni+0x1d3ab8 (000007fe`f6dc3ab8) (System.Threading.Thread.SpinWaitInternal(Int32), mdToken: 000000000600169d) 000007fe`f6e389ac 0f1f4000 nop dword ptr [rax] 000007fe`f6e389b0 488b9db0000000 mov rbx,qword ptr [rbp+0B0h] 000007fe`f6e389b7 803b00 cmp byte ptr [rbx],0 000007fe`f6e389ba b901000000 mov ecx,1 000007fe`f6e389bf 33c0 xor eax,eax 000007fe`f6e389c1 f00fb14b6c lock cmpxchg dword ptr [rbx+6Ch],ecx >>> 000007fe`f6e389c6 83f802 cmp eax,2 000007fe`f6e389c9 74d7 je System_ni+0x2489a2 (000007fe`f6e389a2) //------------------ 반복 끝 ------------------------------</span> ...[생략]... 000007fe`f6e389cb 83f801 cmp eax,1 000007fe`f75dc4fd 5e pop rsi 000007fe`f75dc4fe 5d pop rbp 000007fe`f75dc4ff 5b pop rbx 000007fe`f75dc500 c3 ret </pre> <br /> .NET Reflector로 확인해 보면 다음의 코드에서 무한 루프가 발생한 것입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > protected virtual void Dispose(bool disposing) { if (disposing) { int num; try { if (s_LoggingEnabled) { Logging.Enter(Logging.Sockets, this, "Dispose", (string) null); } } catch (Exception exception) { if (NclUtilities.IsFatal(exception)) { throw; } } <span style='color: blue; font-weight: bold'>while ((num = Interlocked.CompareExchange(ref this.m_IntCleanedUp, 1, 0)) == 2)</span> { Thread.SpinWait(1); } ...[생략]... } } </pre> <br /> 이 때의 소켓 인스턴스가 가진 m_IntCleanedUp 값을 확인하니... 정말로 2였습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:004> <span style='color: blue; font-weight: bold'>!do 00000000014e2230</span> Name: System.Net.Sockets.Socket MethodTable: 000007fef6f13cd8 EEClass: 000007fef6c088c8 Size: 136(0x88) bytes File: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll Fields: MT Field Offset Type VT Attr Value Name 000007fef7db5a60 40025f6 8 System.Object 0 instance 00000000014e2790 m_AcceptQueueOrConnectResult 000007fef6f1ede0 40025f7 10 ...t.SafeCloseSocket 0 instance 00000000014e22d8 m_Handle ...[생략]... 000007fef7dbc7f0 400260f 68 System.Int32 1 instance 0 m_CloseTimeout <span style='color: blue; font-weight: bold'>000007fef7dbc7f0 4002610 6c System.Int32 1 instance 2 m_IntCleanedUp</span> 000007fef7dbd620 4002605 c20 System.Boolean 1 static 0 UseOverlappedIO ...[생략]... 000007fef7dbd620 4002618 c3c System.Boolean 1 static 0 s_PerfCountersEnabled </pre> <br /> 즉, m_IntCleanedUp 값이 2였으니 당연히 "while ((num = Interlocked.CompareExchange(ref this.m_IntCleanedUp, 1, 0)) == 2)" 루프 문을 절대로 빠져나올 수 없습니다. 정말 그런지 다음과 같은 코드로 재현해 볼 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > using System; using System.Net.Sockets; using System.Reflection; class Program { static void Main(string[] args) { Socket socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); OutputMemeber(socket); <span style='color: blue; font-weight: bold'>SetCleanedUpField(socket, 2);</span> OutputMemeber(socket); <span style='color: blue; font-weight: bold'>socket.Dispose(); // 이 호출에서 CPU 100% 현상 발생</span> } private static void SetCleanedUpField(Socket socket, int newValue) { FieldInfo field = typeof(Socket).GetField("m_IntCleanedUp", System.Reflection.BindingFlags.NonPublic | System.Reflection.BindingFlags.Instance); if (field == null) { return; } field.SetValue(socket, newValue); } private static void OutputMemeber(Socket socket) { FieldInfo field = typeof(Socket).GetField("m_IntCleanedUp", System.Reflection.BindingFlags.NonPublic | System.Reflection.BindingFlags.Instance); if (field == null) { return; } object objValue = field.GetValue(socket); if (objValue == null) { return; } Console.WriteLine("m_IntCleanedUp: " + objValue); } } </pre> <br /> 일단, 원인은 알아냈고 그럼 m_IntCleanedUp 값이 언제 2가 되는 걸까요? .NET Reflector에서 m_IntCleanedUp 멤버로 Analyze 메뉴를 실행하면 다음과 같이 해당 필드 값이 사용된 코드를 분석할 수 있습니다.<br /> <br /> <img onclick='toggle_img(this)' class='imgView' alt='windbg_async_socket_infinite_loop_1.png' src='/SysWebRes/bbs/windbg_async_socket_infinite_loop_1.png' /><br /> <br /> 위의 결과로 보면, Socket.Dispose, Socket.get_CleanedUp, Socket.SetAsyncEventSelect 메서드에서 사용되고 있는데, 이 중에서 Dispose는 우리가 지금 겪고 있는 문제의 함수이고 get_CleanedUp의 코드를 가보면,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > internal bool get_CleanedUp() { return (this.m_IntCleanedUp == 1); } </pre> <br /> 값을 변경하지 않고 있으니, 마지막 Socket.SetAsyncEventSelect 메서드가 우리가 찾는 메서드가 됩니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > private bool SetAsyncEventSelect(AsyncEventBits blockEventBits) { if (this.m_RegisteredWait != null) { return false; } if (this.m_AsyncEvent == null) { Interlocked.CompareExchange<ManualResetEvent>(ref this.m_AsyncEvent, new ManualResetEvent(false), null); if (s_RegisteredWaitCallback == null) { s_RegisteredWaitCallback = new WaitOrTimerCallback(Socket.RegisteredWaitCallback); } } <span style='color: blue; font-weight: bold'>if (Interlocked.CompareExchange(ref this.m_IntCleanedUp, 2, 0) != 0)</span> { return false; } try { this.m_BlockEventBits = blockEventBits; this.m_RegisteredWait = ThreadPool.UnsafeRegisterWaitForSingleObject(this.m_AsyncEvent, s_RegisteredWaitCallback, this, -1, true); } finally { <span style='color: blue; font-weight: bold'>Interlocked.Exchange(ref this.m_IntCleanedUp, 0);</span> } // ...[생략]... return (notSocket == SocketError.Success); } </pre> <br /> 보시는 바와 같이, SetAsyncEventSelect 메서드는 m_IntCleanedUp을 2로 바꾼 후, 거의 곧바로 finally 블록에서 다시 0으로 바꿔줍니다. 즉, 이 문제가 재현되려면 0으로 바꾸는 사이에 해당 스레드가 비정상 종료되어야만 하는 희귀한 조건인 것입니다.<br /> <br /> 더욱 재미있는 것은, 문제가 된 사용자 코드는 전형적인/매우 간단한 WebClient 코드였다는 점입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > WebClient wc = new WebClient(); wc.Timeout = 15000; wc.DownloadStringCompleted += (s, e) => { }; wc.DownloadStringAsync(new Uri(path)); </pre> <br /> 결국 비동기 호출에서 영향을 받았기 때문에, 일단 동기 호출이어도 문제가 없으므로 현재는 비동기 호출을 하지 않도록 바꾼 상태입니다. 오늘은 여기까지만! ^^<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
2083
(왼쪽의 숫자를 입력해야 합니다.)