Microsoft MVP성태의 닷넷 이야기
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일
 
(연관된 글이 1개 있습니다.)
(시리즈 글이 7개 있습니다.)
.NET Framework: 394. async/await 사용 시 hang 문제가 발생하는 경우
; https://www.sysnet.pe.kr/2/0/1541

.NET Framework: 512. async/await 사용 시 hang 문제가 발생하는 경우 - 두 번째 이야기
; https://www.sysnet.pe.kr/2/0/10801

.NET Framework: 631. async/await에 대한 "There Is No Thread" 글의 부가 설명
; https://www.sysnet.pe.kr/2/0/11129

.NET Framework: 720. 비동기 메서드 내에서 await 시 ConfigureAwait 호출 의미
; https://www.sysnet.pe.kr/2/0/11418

.NET Framework: 721. WebClient 타입의 ...Async 메서드 호출은 왜 await + 동기 호출 시 hang 현상이 발생할까요?
; https://www.sysnet.pe.kr/2/0/11419

디버깅 기술: 196. windbg - async/await 비동기인 경우 메모리 덤프 분석의 어려움
; https://www.sysnet.pe.kr/2/0/13563

닷넷: 2225. Windbg - dumasync로 분석하는 async/await 호출
; https://www.sysnet.pe.kr/2/0/13573




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 돼 내려갈 수밖에 없는 것입니다.

어떠세요? 만약 현업에서 저런 문제를 겪는 덤프를 뜨게 된다면... 문제의 원인을 찾아갈 수 있을까요? ^^;




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]

[연관 글]






[최초 등록일: ]
[최종 수정일: 3/14/2024]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer at outlook.com

비밀번호

댓글 작성자
 




[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
13602정성태4/20/2024220닷넷: 2244. C# - PCM 오디오 데이터를 연속(Streaming) 재생 (Windows Multimedia)파일 다운로드1
13601정성태4/19/2024257닷넷: 2243. C# - PCM 사운드 재생(NAudio)파일 다운로드1
13600정성태4/18/2024298닷넷: 2242. C# - 관리 스레드와 비관리 스레드
13599정성태4/17/2024439닷넷: 2241. C# - WAV 파일의 PCM 사운드 재생(Windows Multimedia)파일 다운로드1
13598정성태4/16/2024436닷넷: 2240. C# - WAV 파일 포맷 + LIST 헤더파일 다운로드2
13597정성태4/15/2024502닷넷: 2239. C# - WAV 파일의 PCM 데이터 생성 및 출력파일 다운로드1
13596정성태4/14/2024853닷넷: 2238. C# - WAV 기본 파일 포맷파일 다운로드1
13595정성태4/13/2024984닷넷: 2237. C# - Audio 장치 열기 (Windows Multimedia, NAudio)파일 다운로드1
13594정성태4/12/20241033닷넷: 2236. C# - Audio 장치 열람 (Windows Multimedia, NAudio)파일 다운로드1
13593정성태4/8/20241052닷넷: 2235. MSBuild - AccelerateBuildsInVisualStudio 옵션
13592정성태4/2/20241209C/C++: 165. CLion으로 만든 Rust Win32 DLL을 C#과 연동
13591정성태4/2/20241169닷넷: 2234. C# - WPF 응용 프로그램에 Blazor App 통합파일 다운로드1
13590정성태3/31/20241073Linux: 70. Python - uwsgi 응용 프로그램이 k8s 환경에서 OOM 발생하는 문제
13589정성태3/29/20241143닷넷: 2233. C# - 프로세스 CPU 사용량을 나타내는 성능 카운터와 Win32 API파일 다운로드1
13588정성태3/28/20241197닷넷: 2232. C# - Unity + 닷넷 App(WinForms/WPF) 간의 Named Pipe 통신파일 다운로드1
13587정성태3/27/20241157오류 유형: 900. Windows Update 오류 - 8024402C, 80070643
13586정성태3/27/20241304Windows: 263. Windows - 복구 파티션(Recovery Partition) 용량을 늘리는 방법
13585정성태3/26/20241096Windows: 262. PerformanceCounter의 InstanceName에 pid를 추가한 "Process V2"
13584정성태3/26/20241050개발 환경 구성: 708. Unity3D - C# Windows Forms / WPF Application에 통합하는 방법파일 다운로드1
13583정성태3/25/20241158Windows: 261. CPU Utilization이 100% 넘는 경우를 성능 카운터로 확인하는 방법
13582정성태3/19/20241421Windows: 260. CPU 사용률을 나타내는 2가지 수치 - 사용량(Usage)과 활용률(Utilization)파일 다운로드1
13581정성태3/18/20241589개발 환경 구성: 707. 빌드한 Unity3D 프로그램을 C++ Windows Application에 통합하는 방법
13580정성태3/15/20241138닷넷: 2231. C# - ReceiveTimeout, SendTimeout이 적용되지 않는 Socket await 비동기 호출파일 다운로드1
13579정성태3/13/20241494오류 유형: 899. HTTP Error 500.32 - ANCM Failed to Load dll
13578정성태3/11/20241631닷넷: 2230. C# - 덮어쓰기 가능한 환형 큐 (Circular queue)파일 다운로드1
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...