windbg - async/await 비동기인 경우 메모리 덤프 분석의 어려움
비교를 위해 동기인 경우를 먼저 보겠습니다. ^^ 가령, 아래의 코드는 이전에 소개한 blocking 예제입니다.
Socket client = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp);
client.Connect("192.168.100.50", 15000);
int length = client.SendBufferSize;
while (true)
{
byte[] buf = new byte[length];
client.Send(buf, 0, buf.Length, SocketFlags.None);
}
TCP Server 측에서 Receive를 하지 않는다면 3MB 정도를 send하고는 client.Send에서 blocking이 걸립니다. 이런 경우, 메모리 덤프를 떠서 이후에 분석할 때를 가정해 볼까요? ^^
위의 경우에는 간단하게 clrstack을 하면 Send 호출에 걸려 있는 것을 쉽게 발견할 수 있습니다.
0:000> !clrstack
OS Thread Id: 0x10314 (0)
Child SP IP Call Site
00eff00c 76f8671c [InlinedCallFrame: 00eff00c]
00eff008 70dbb6a4 DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
00eff00c 70d62a1a [InlinedCallFrame: 00eff00c] System.Net.UnsafeNclNativeMethods+OSSOCK.send(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
00eff044 70d62a1a System.Net.Sockets.Socket.Send(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef) [f:\dd\NDP\fx\src\net\System\Net\Sockets\Socket.cs @ 1549]
00eff078 70d628ce System.Net.Sockets.Socket.Send(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags) [f:\dd\NDP\fx\src\net\System\Net\Sockets\Socket.cs @ 1510]
00eff098 01690983 ConsoleApp2.Program.Main(System.String[])
00eff2a0 73ff2546 [GCFrame: 00eff2a0]
게다가 스레드 상태도 간단한데요,
0:000> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 10314 010f0ef8 2a020 Preemptive 033F9238:00000000 010eabb8 0 MTA
5 2 7fb0 01101378 2b220 Preemptive 00000000:00000000 010eabb8 0 MTA (Finalizer)
보는 바와 같이 Main 스레드 하나와 Finalizer 스레드 한 개만 있어 직관적으로 분석하기에도 편합니다.
자, 그럼 위의 예제를 비동기로 바꿔보겠습니다.
TcpClient client = new TcpClient();
client.Connect("192.168.100.50", 15000);
NetworkStream ns = client.GetStream();
int length = client.SendBufferSize;
while (true)
{
byte[] buf = new byte[length];
await ns.WriteAsync(buf, 0, buf.Length, ct.Token);
}
마찬가지로 (서버에서 받아주지 않으면) 3MB 정도 전송 후에는 더 이상 await 이후의 코드로 나아가지 못합니다. 단지, 동기 메서드를 호출했을 때와 상황은 다른데요, blocking이 걸린 것은 아니고 콜백을 받지 못하는 현상입니다.
단순한 Console 예제인데도, WriteAsync 호출로 인해 스레드 풀이 사용되면서 스레드 상황도 복잡하게 나옵니다.
0:010> !threads
ThreadCount: 9
UnstartedThread: 0
BackgroundThread: 4
PendingThread: 0
DeadThread: 4
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 9f4c 00000288987D6D80 202a020 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 MTA
6 2 d444 00000288987DAD20 2b220 Preemptive 000002889CC126B0:000002889CC142C8 00000288987c0b30 -00001 MTA (Finalizer)
XXXX 4 0 000002889A358EA0 1039820 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 Ukn (Threadpool Worker)
7 5 d45c 0000028880409C00 302b220 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 MTA (Threadpool Worker)
XXXX 6 0 0000028880408930 1039820 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 Ukn (Threadpool Worker)
XXXX 7 0 0000028880407920 1039820 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 Ukn (Threadpool Worker)
8 8 d468 0000028880478F00 102b220 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 MTA (Threadpool Worker)
9 9 d46c 0000028880481550 102b220 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 MTA (Threadpool Worker)
XXXX 10 0 0000028880495FB0 1039820 Preemptive 0000000000000000:0000000000000000 00000288987c0b30 -00001 Ukn (Threadpool Worker)
"DBG" 칼럼에 "XXXX"로 나온 것은 종료된 스레드이므로 나머지 9f4c, (d444는 finalizer 스레드이므로 제외), d45c, d468, d46c 스레드에 대해서만 호출 스택을 살펴보면 이렇게 나옵니다.
OS Thread Id: 0x9f4c (0)
Child SP IP Call Site
0000008F1C97E778 00007ffb6222fec4 [HelperMethodFrame_1OBJ: 0000008f1c97e778] System.Threading.Monitor.ObjWait(Int32, System.Object)
0000008F1C97E8A0 00007ffad62ed5ae System.Threading.Monitor.Wait(System.Object, Int32) [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Monitor.CoreCLR.cs @ 156]
0000008F1C97E8D0 00007ffad62f850e System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ManualResetEventSlim.cs @ 561]
0000008F1C97E970 00007ffad63114b9 System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 3072]
0000008F1C97E9F0 00007ffad63112a6 System.Threading.Tasks.Task.InternalWaitCore(Int32, System.Threading.CancellationToken) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 3007]
0000008F1C97EA70 00007ffad63632e5 System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task, System.Threading.Tasks.ConfigureAwaitOptions) [/_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/TaskAwaiter.cs @ 104]
0000008F1C97EAB0 00007ffa799b2e7a ConsoleApp5.Program.(System.String[])
OS Thread Id: 0xd45c (7)
Child SP IP Call Site
0000008F1D5BF678 00007ffb6222fec4 [HelperMethodFrame: 0000008f1d5bf678] System.Threading.WaitHandle.WaitOneCore(IntPtr, Int32)
0000008F1D5BF780 00007ffad62f0bd4 System.Threading.WaitHandle.WaitOneNoCheck(Int32) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/WaitHandle.cs @ 128]
0000008F1D5BF7E0 00007ffad6308f36 System.Threading.PortableThreadPool+GateThread.GateThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.GateThread.cs @ 48]
0000008F1D5BFB70 00007ffad951a1a3 [DebuggerU2MCatchHandlerFrame: 0000008f1d5bfb70]
OS Thread Id: 0xd468 (8)
Child SP IP Call Site
0000008F1D8FF790 00007ffb62232304 [InlinedCallFrame: 0000008f1d8ff790]
0000008F1D8FF790 00007ffad630ad70 [InlinedCallFrame: 0000008f1d8ff790]
0000008F1D8FF750 00007ffad630ad70 System.Threading.PortableThreadPool+IOCompletionPoller.Poll() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.IO.Windows.cs @ 188]
0000008F1D8FFAB0 00007ffad951a1a3 [DebuggerU2MCatchHandlerFrame: 0000008f1d8ffab0]
OS Thread Id: 0xd46c (9)
Child SP IP Call Site
0000008F1D93F440 00007ffb62232304 [InlinedCallFrame: 0000008f1d93f440]
0000008F1D93F440 00007ffad630ad70 [InlinedCallFrame: 0000008f1d93f440]
0000008F1D93F400 00007ffad630ad70 System.Threading.PortableThreadPool+IOCompletionPoller.Poll() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.IO.Windows.cs @ 188]
0000008F1D93F760 00007ffad951a1a3 [DebuggerU2MCatchHandlerFrame: 0000008f1d93f760]
보는 바와 같이 어떤 스레드 호출 스택에서도 WriteAsync에 대한 내용이 없습니다. 왜냐하면, 비동기 모델에서는 WriteAsync 호출 시 I/O Request를 커널에 전달하고 스레드 제어를 반환하므로 해당 스레드는 이미 스레드풀에 돌아가 다음 처리를 받을 준비 상태로 빠지기 때문입니다.
다시 말해, 특정 응용 프로그램이 hang 상태에 빠졌을 때 도대체 어떤 호출로 인해 그런 것인지 알아내기가 힘들어졌다는 것입니다.
위와 같은 문제 때문에 .NET Core 3+부터는
sos에 dumpasync 명령어가 추가되긴 했는데요, 이 부분에 대해서는
별도의 글로 미루고 그냥 원칙에 기반해 위의 덤프를 좀 더 분석해 보겠습니다.
일단, 대개의 경우 문제가 없는지 힙을 확인하는 것으로 시작할 수 있습니다.
0:010> !dumpheap
...[생략]...
7ffa79b17558 3 864 System.GCMemoryInfoData
7ffa79a62b28 14 896 System.Diagnostics.Tracing.EventSource+OverrideEventProvider
7ffa79abd1f8 2 912 System.Buffers.SharedArrayPool<System.Char>+ThreadLocalArray[]
7ffa79a9c850 15 960 System.Reflection.RuntimeModule
7ffa798e5fa8 42 1,008 System.Object
7ffa79b10c10 2 1,072 System.Collections.Concurrent.ConcurrentQueueSegment<System.Object>+Slot[]
7ffa79bd6258 2 1,584 System.Collections.Concurrent.ConcurrentQueueSegment<System.Threading.PortableThreadPool+IOCompletionPoller+Event>+Slot[]
7ffa79a69aa0 5 1,726 System.Char[]
7ffa798ea318 44 1,760 System.RuntimeType
7ffa79c46860 22 1,760 System.Threading.Tasks.ValueTask+ValueTaskSourceAsTask
7ffa79999df8 12 3,756 System.Int32[]
7ffa79bb77e0 1 4,024 System.Threading.PortableThreadPool+HillClimbing+LogEntry[]
7ffa79a3fa88 27 4,096 System.String[]
7ffa79bbd968 226 5,424 System.Reflection.Emit.OpCode
7ffa798ec4d8 21 35,488 System.Object[]
0288987f9410 54 44,712 Free
7ffa7999ec08 460 58,360 System.String
7ffa79b18d20 40 1,444,737 System.Byte[]
byte[] 타입의 크기가 눈에 띄는군요. ^^ 덤프를 해보면,
0:010> !dumpheap -mt 7ffa79b18d20
Address MT Size
0288800076e8 7ffa79b18d20 24
02889c80e570 7ffa79b18d20 41
...[생략]...
02889c811e78 7ffa79b18d20 45
02889c812198 7ffa79b18d20 40
02889c812638 7ffa79b18d20 1,048
02889c814000 7ffa79b18d20 424
02889c8141a8 7ffa79b18d20 224
02889c814c00 7ffa79b18d20 65,560
02889cc00270 7ffa79b18d20 65,560
02889cc1bcc0 7ffa79b18d20 25
02889cc1bd68 7ffa79b18d20 65,560
02889cc2be90 7ffa79b18d20 65,560
02889cc3bfa0 7ffa79b18d20 65,560
02889cc4c0b0 7ffa79b18d20 65,560
02889cc5c1c0 7ffa79b18d20 65,560
02889cc6c2d0 7ffa79b18d20 65,560
02889cc7c3e0 7ffa79b18d20 65,560
02889cc8c4f0 7ffa79b18d20 65,560
02889cc9c600 7ffa79b18d20 65,560
02889ccac710 7ffa79b18d20 65,560
02889ccbc820 7ffa79b18d20 65,560
02889cccc930 7ffa79b18d20 65,560
02889ccdca40 7ffa79b18d20 65,560
02889ccecb50 7ffa79b18d20 65,560
02889ccfcc60 7ffa79b18d20 65,560
02889cd0cd70 7ffa79b18d20 65,560
02889cd1ce80 7ffa79b18d20 65,560
02889cd2cf90 7ffa79b18d20 65,560
02889cd3d0a0 7ffa79b18d20 65,560
02889cd4d1b0 7ffa79b18d20 65,560
고르게 65,560 바이트들이 나오는데, 이것은 Send 시 지정했던 버퍼의 크기 때문입니다.
TcpClient client = new TcpClient();
...[생략]...
int length = client.SendBufferSize; // 65,560
while (true)
{
byte[] buf = new byte[length];
await ns.WriteAsync(buf, 0, buf.Length, ct.Token);
}
하지만 테스트라서 운이 좋았던 것일 뿐, 아마도 실제 응용 프로그램이었다면 전송 데이터가 가변적인 경우가 많을 것입니다. 어쨌든, 일단 저것들 중에 하나를 선택해 소유 개체를 찾아보면,
0:010> !gcroot 02889cd4d1b0
Caching GC roots, this may take a while.
Subsequent runs of this command will be faster.
HandleTable:
00000288987612a8 (strong handle)
-> 02889c8149f8 System.Threading.ThreadPoolBoundHandleOverlapped
-> 02889c814920 System.Runtime.CompilerServices.StrongBox<System.Net.Sockets.SocketAsyncEventArgs>
-> 02889c814790 System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs
-> 02889cd4d1b0 System.Byte[]
00000288987615e8 (pinned handle)
-> 02889cd4d1b0 System.Byte[]
Found 2 unique roots.
버퍼가 pinning 상태로 나옵니다. 왜냐하면, 비동기 I/O 호출을 하게 되면 Win32를 거쳐 커널로 데이터가 전송되기 때문에 닷넷의 버퍼는 무조건 pinning 돼 내려갈 수밖에 없는 것입니다.
어떠세요? 만약 현업에서 저런 문제를 겪는 덤프를 뜨게 된다면... 문제의 원인을 찾아갈 수 있을까요? ^^;
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]