성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] 제가 큰 실수를 했군요. ^^; 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 - async/await 비동기인 경우 메모리 덤프 분석의 어려움</h1> <p> 비교를 위해 동기인 경우를 먼저 보겠습니다. ^^ 가령, 아래의 코드는 <a target='tab' href='https://www.sysnet.pe.kr/2/0/13561'>이전에 소개한 blocking 예제</a>입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > Socket client = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); client.Connect("192.168.100.50", 15000); int length = client.SendBufferSize; <span style='color: blue; font-weight: bold'>while (true)</span> { byte[] buf = new byte[length]; <span style='color: blue; font-weight: bold'>client.Send(buf, 0, buf.Length, SocketFlags.None); </span> } </pre> <br /> TCP Server 측에서 Receive를 하지 않는다면 3MB 정도를 send하고는 client.Send에서 blocking이 걸립니다. 이런 경우, 메모리 덤프를 떠서 이후에 분석할 때를 가정해 볼까요? ^^<br /> <br /> 위의 경우에는 간단하게 clrstack을 하면 Send 호출에 걸려 있는 것을 쉽게 발견할 수 있습니다.<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'>!clrstack</span> 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] <span style='color: blue; font-weight: bold'>System.Net.UnsafeNclNativeMethods+OSSOCK.send</span>(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] </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'>!threads</span> 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) </pre> <br /> 보는 바와 같이 Main 스레드 하나와 Finalizer 스레드 한 개만 있어 직관적으로 분석하기에도 편합니다.<br /> <br /> <hr style='width: 50%' /><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;' > 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]; <span style='color: blue; font-weight: bold'>await ns.WriteAsync(buf, 0, buf.Length, ct.Token);</span> } </pre> <br /> 마찬가지로 (서버에서 받아주지 않으면) 3MB 정도 전송 후에는 더 이상 await 이후의 코드로 나아가지 못합니다. 단지, 동기 메서드를 호출했을 때와 상황은 다른데요, blocking이 걸린 것은 아니고 콜백을 받지 못하는 현상입니다.<br /> <br /> 단순한 Console 예제인데도, WriteAsync 호출로 인해 스레드 풀이 사용되면서 스레드 상황도 복잡하게 나옵니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:010> <span style='color: blue; font-weight: bold'>!threads</span> 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) </pre> <br /> "DBG" 칼럼에 "XXXX"로 나온 것은 종료된 스레드이므로 나머지 9f4c, (d444는 finalizer 스레드이므로 제외), d45c, d468, d46c 스레드에 대해서만 호출 스택을 살펴보면 이렇게 나옵니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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] </pre> <br /> 보는 바와 같이 어떤 스레드 호출 스택에서도 WriteAsync에 대한 내용이 없습니다. 왜냐하면, 비동기 모델에서는 WriteAsync 호출 시 I/O Request를 커널에 전달하고 스레드 제어를 반환하므로 해당 스레드는 이미 스레드풀에 돌아가 다음 처리를 받을 준비 상태로 빠지기 때문입니다.<br /> <br /> 다시 말해, 특정 응용 프로그램이 hang 상태에 빠졌을 때 도대체 어떤 호출로 인해 그런 것인지 알아내기가 힘들어졌다는 것입니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 위와 같은 문제 때문에 .NET Core 3+부터는 <a target='tab' href='https://learn.microsoft.com/en-us/dotnet/core/diagnostics/sos-debugging-extension#commands'>sos에 dumpasync 명령어</a>가 추가되긴 했는데요, 이 부분에 대해서는 <a target='tab' href='https://www.sysnet.pe.kr/2/0/13573'>별도의 글</a>로 미루고 그냥 원칙에 기반해 위의 덤프를 좀 더 분석해 보겠습니다.<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;' > 0:010> <span style='color: blue; font-weight: bold'>!dumpheap</span> ...[생략]... 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 <span style='color: blue; font-weight: bold'>7ffa79b18d20 40 1,444,737 System.Byte[]</span> </pre> <br /> byte[] 타입의 크기가 눈에 띄는군요. ^^ 덤프를 해보면,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:010> <span style='color: blue; font-weight: bold'>!dumpheap -mt 7ffa79b18d20</span> 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 <span style='color: blue; font-weight: bold'>02889c814c00 7ffa79b18d20 65,560 02889cc00270 7ffa79b18d20 65,560</span> 02889cc1bcc0 7ffa79b18d20 25 <span style='color: blue; font-weight: bold'>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</span> </pre> <br /> 고르게 65,560 바이트들이 나오는데, 이것은 Send 시 지정했던 버퍼의 크기 때문입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > TcpClient client = new TcpClient(); ...[생략]... <span style='color: blue; font-weight: bold'>int length = client.SendBufferSize;</span> // 65,560 while (true) { <span style='color: blue; font-weight: bold'>byte[] buf = new byte[length];</span> await ns.WriteAsync(buf, 0, buf.Length, ct.Token); } </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:010> <span style='color: blue; font-weight: bold'>!gcroot 02889cd4d1b0</span> Caching GC roots, this may take a while. Subsequent runs of this command will be faster. HandleTable: <span style='color: blue; font-weight: bold'>00000288987612a8 (strong handle)</span> -> 02889c8149f8 System.Threading.ThreadPoolBoundHandleOverlapped -> 02889c814920 System.Runtime.CompilerServices.StrongBox<System.Net.Sockets.SocketAsyncEventArgs> -> 02889c814790 System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs -> 02889cd4d1b0 System.Byte[] <span style='color: blue; font-weight: bold'>00000288987615e8 (pinned handle)</span> -> 02889cd4d1b0 System.Byte[] Found 2 unique roots. </pre> <br /> 버퍼가 pinning 상태로 나옵니다. 왜냐하면, 비동기 I/O 호출을 하게 되면 Win32를 거쳐 커널로 데이터가 전송되기 때문에 닷넷의 버퍼는 무조건 pinning 돼 내려갈 수밖에 없는 것입니다.<br /> <br /> 어떠세요? 만약 현업에서 저런 문제를 겪는 덤프를 뜨게 된다면... 문제의 원인을 찾아갈 수 있을까요? ^^;<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
4423
(왼쪽의 숫자를 입력해야 합니다.)