windbg 분석 사례 - cpu 100% 현상 (2)
CPU 100% 현상이 연 이어 두번 나오는 군요.
windbg 분석 사례 - cpu 100% 현상 (1)
; https://www.sysnet.pe.kr/2/0/1831
유경험자니까 ^^ 이젠 바로 문제 분석 단계로 내려갑니다.
0:000> !runaway
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
4번 스레드로 문맥 전환하고,
0:000> ~4s
*** WARNING: Unable to verify checksum for System.ni.dll
clr!ThreadNative::SpinWait+0x25:
000007fe`f8f38fa5 4c8d25d4ffffff lea r12,[clr!ThreadNative::SpinWait (000007fe`f8f38f80)]
스택을 보려는데... ^^; 안 나옵니다.
0:004> !clrstack
OS Thread Id: 0x67c (4)
Child SP IP Call Site
000000001a88f538 000007fef8f38fa5 [GCFrame: 000000001a88f538]
000000001a88f920 000007fef8f38fa5 [DebuggerU2MCatchHandlerFrame: 000000001a88f920]
일단 포기하고, dumpstack으로 우회합니다.
0:004> !dumpstack
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
그런데, 재미있군요. 실행된 프로세스에 직접 attach 해보니 다음과 같이 !clrstack이 잘 나옵니다.
0:004> !clrstack
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]
이상하군요.Socket.Dispose(Boolean) 메서드에서 CPU 100% 현상이 발생하다니... 제가 뭔가 잘못한 걸까요? 일단 CPU 100% 현상의 무한 루프에 대한 시작/끝 점을 알기 위해 기계어로 덤프한 후 예전의 글에서 설명했던 것처럼 따라가 보니 다음의 구간을 찾을 수 있었습니다.
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)
//------------------ 반복 시작 ------------------------------
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)
//------------------ 반복 끝 ------------------------------
...[생략]...
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
.NET Reflector로 확인해 보면 다음의 코드에서 무한 루프가 발생한 것입니다.
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;
}
}
while ((num = Interlocked.CompareExchange(ref this.m_IntCleanedUp, 1, 0)) == 2)
{
Thread.SpinWait(1);
}
...[생략]...
}
}
이 때의 소켓 인스턴스가 가진 m_IntCleanedUp 값을 확인하니... 정말로 2였습니다.
0:004> !do 00000000014e2230
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
000007fef7dbc7f0 4002610 6c System.Int32 1 instance 2 m_IntCleanedUp
000007fef7dbd620 4002605 c20 System.Boolean 1 static 0 UseOverlappedIO
...[생략]...
000007fef7dbd620 4002618 c3c System.Boolean 1 static 0 s_PerfCountersEnabled
즉, m_IntCleanedUp 값이 2였으니 당연히 "while ((num = Interlocked.CompareExchange(ref this.m_IntCleanedUp, 1, 0)) == 2)" 루프 문을 절대로 빠져나올 수 없습니다. 정말 그런지 다음과 같은 코드로 재현해 볼 수 있습니다.
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);
SetCleanedUpField(socket, 2);
OutputMemeber(socket);
socket.Dispose(); // 이 호출에서 CPU 100% 현상 발생
}
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);
}
}
일단, 원인은 알아냈고 그럼 m_IntCleanedUp 값이 언제 2가 되는 걸까요? .NET Reflector에서 m_IntCleanedUp 멤버로 Analyze 메뉴를 실행하면 다음과 같이 해당 필드 값이 사용된 코드를 분석할 수 있습니다.
위의 결과로 보면, Socket.Dispose, Socket.get_CleanedUp, Socket.SetAsyncEventSelect 메서드에서 사용되고 있는데, 이 중에서 Dispose는 우리가 지금 겪고 있는 문제의 함수이고 get_CleanedUp의 코드를 가보면,
internal bool get_CleanedUp()
{
return (this.m_IntCleanedUp == 1);
}
값을 변경하지 않고 있으니, 마지막 Socket.SetAsyncEventSelect 메서드가 우리가 찾는 메서드가 됩니다.
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);
}
}
if (Interlocked.CompareExchange(ref this.m_IntCleanedUp, 2, 0) != 0)
{
return false;
}
try
{
this.m_BlockEventBits = blockEventBits;
this.m_RegisteredWait = ThreadPool.UnsafeRegisterWaitForSingleObject(this.m_AsyncEvent, s_RegisteredWaitCallback, this, -1, true);
}
finally
{
Interlocked.Exchange(ref this.m_IntCleanedUp, 0);
}
// ...[생략]...
return (notSocket == SocketError.Success);
}
보시는 바와 같이, SetAsyncEventSelect 메서드는 m_IntCleanedUp을 2로 바꾼 후, 거의 곧바로 finally 블록에서 다시 0으로 바꿔줍니다. 즉, 이 문제가 재현되려면 0으로 바꾸는 사이에 해당 스레드가 비정상 종료되어야만 하는 희귀한 조건인 것입니다.
더욱 재미있는 것은, 문제가 된 사용자 코드는 전형적인/매우 간단한 WebClient 코드였다는 점입니다.
WebClient wc = new WebClient();
wc.Timeout = 15000;
wc.DownloadStringCompleted += (s, e) => { };
wc.DownloadStringAsync(new Uri(path));
결국 비동기 호출에서 영향을 받았기 때문에, 일단 동기 호출이어도 문제가 없으므로 현재는 비동기 호출을 하지 않도록 바꾼 상태입니다. 오늘은 여기까지만! ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]