Windbg - dumasync로 분석하는 async/await 호출
다음의 문서에 dumpasync 소개가 간략하게 나오는데요,
SOS debugging extension
; https://learn.microsoft.com/en-us/dotnet/core/diagnostics/sos-debugging-extension#commands
DumpAsync traverses the garbage collected heap and looks for objects representing async state machines as created when an async method's state is transferred to the heap.
약간 문서가 오래된 듯하니, 차라리 windbg 내에서 sos 확장의 help 출력을 보는 것이 더 좋습니다.
0:026> !sos.help dumpasync
dumpasync:
Displays information about async "stacks" on the garbage-collected heap.
Usage:
>!sos dumpasync [options]
Options:
-addr, --address <address> Only show stacks that include the object with the specified address.
-mt, --methodtable <methodtable> Only show stacks that include objects with the specified method table.
--type <type> Only show stacks that include objects whose type includes the specified name in its name.
-t, --tasks Include stacks that contain only non-state machine task objects.
-c, --completed Include completed tasks in stacks.
-f, --fields Show state machine fields for every async stack frame that has them.
--stats Summarize all async frames found rather than showing detailed stacks.
--coalesce Coalesce stacks and portions of stacks that are the same.
Displays information about async "stacks" on the garbage-collected heap. Stacks
are synthesized by finding all task objects (including async state machine box
objects) on the GC heap and chaining them together based on continuations.
Examples:
Summarize all async frames associated with a specific method table address: dumpasync --stats --methodtable 0x00007ffbcfbe0970
Show all stacks coalesced by common frames: dumpasync --coalesce
Show each stack that includes "ReadAsync": dumpasync --type ReadAsync
Show each stack that includes an object at a specific address, and include fields: dumpasync --address 0x000001264adce778 --fields
부가적으로 다음의 문서도 참고하시고.
NET Core 3. !dumpasync
; https://github.com/Microsoft/vs-threading/blob/main/doc/dumpasync.md
Threading documentation
; https://github.com/microsoft/vs-threading/blob/main/doc/index.md
일단, 문서는 그렇고 실제로 실습을 해볼까요? ^^ 예제는 지난 글에서 소개한 것을 그대로 사용하겠습니다.
async/await 사용 시 hang 문제가 발생하는 경우
; https://www.sysnet.pe.kr/2/0/1541
단지, dumpasync 명령어가 .NET Core 3부터 지원하기 때문에 아래의 예제는 .NET 8로 만들었습니다.
// .NET 8 + Debug + x64
private void Window_Loaded(object sender, RoutedEventArgs e)
{
Task<string> task = GetMyText();
this.textBox1.Text = task.Result;
}
async Task<string> GetMyText()
{
await Task.Delay(1);
return "Hello World";
}
위의 코드를 실행하고 (마치) blocking에 걸리면 windbg로 연결해 dumpasync를 실행해 보면 됩니다.
0:007> !dumpasync
STACK 1
<< Awaiting: 0000020d6b82dbf8 00007ff88b6f7590 System.Runtime.CompilerServices.TaskAwaiter >>
0000020d6b82f0e8 00007ff88b6fe408 (0) WpfApp1.MainWindow+<GetMyText>d__12 @ 7ff88b665820
0000020d6b82f1a8 00007ff88b710a10 () System.Threading.Tasks.Task+SetOnInvokeMres
출력 결과가 다소 낯설을 수 있는데요, 찬찬히 뜯어보겠습니다. ^^ 우선, dumpasync가 나열하는 것은 "await ..." 호출로 진행 중인 비동기를 나열합니다.
그리고 괄호 안에 숫자가 있는 것을 볼 수 있는데요, 그것은 C# 컴파일러가 생성한 async 상태 머신의 state 필드 값을 의미합니다.
문서에서는 저 값의 상태를 3가지로 분류해 설명하고 있는데요,
- -2: 비동기 메서드가 완료된 상태, dumasync는 이 값을 갖는 경우 출력에서 제외
- -1: 비동기 메서드가 현재 실행 중인 상태
- >= 0: 대개 0으로, await 호출을 시작한 상태
코드와 함께 설명해 볼까요?
async Task<string> GetMyText()
{
await Task.Delay(1000);
return "Hello World";
}
위의 코드에서 "await Task.Delay(1000)" 호출은
타이머를 시작만 하고 곧바로 제어를 반환할 텐데요, 바로 그때의 state 값이 0이 됩니다. 즉, dumpasync로 상태가 0인 목록이 나열되면 그것들은 모두 await 비동기 호출이 "발행"된 것들을 의미합니다.
그다음, 약 1초 후에 timer는 스레드풀의 여유 스레드를 하나 받아와 await 이후의 코드에 해당하는 "return Hello World;"를 실행할 텐데요, 바로 그 시점에 state 값을 보면 -1이 됩니다. 위와 같은 경우에는 blocking 예제라 -1을 볼 수가 없는데 따라서 테스트를 위해 다음과 같이 코드를 변경한 후,
private void Window_Loaded(object sender, RoutedEventArgs e)
{
Task<string> task = GetMyText();
}
async Task<string> GetMyText()
{
await Task.Delay(1);
Thread.Sleep(-1);
return "Hello World";
}
windbg로 연결해 1ms 이후에 await 이후의 코드를 실행하느라 묶여 있을 때 dumpasync를 내리면 다음과 같은 출력을 얻을 수 있습니다.
0:024> !dumpasync
STACK 1
000002261602f0e8 00007ff88f1ee7b0 (-1) WpfApp1.MainWindow+<GetMyText>d__12 @ 7ff88f1557e0
결국 dumpasync 명령어를 이용하면 await으로 발행된 비동기 메서드의 유무와, await 이후의 코드를 실행 중인 비동기 메서드를 알아낼 수 있습니다.
이번에는 다른 예제로 dumpasync의 출력을 알아보겠습니다. ^^
windbg - async/await 비동기인 경우 메모리 덤프 분석의 어려움
; https://www.sysnet.pe.kr/2/0/13563
위의 예제에서는 (서버에서 recv를 하지 않아) NetworkStream.WriteAsync 호출이 쌓여 await 콜백이 발생하지 못하는 상황까지 가는데요,
private async void Window_Loaded(object sender, RoutedEventArgs e)
{
TcpClient client = new TcpClient();
client.Connect("192.168.100.50", 15000);
NetworkStream ns = client.GetStream();
int length = client.SendBufferSize;
CancellationTokenSource ct = new CancellationTokenSource();
int count = 150;
while (count -- > 0)
{
byte[] buf = new byte[length];
await ns.WriteAsync(buf, 0, buf.Length, ct.Token);
}
this.textBox1.Text = "Sent!";
}
await ns.WriteAsync를 여러 번 호출했지만 TCP buffer에 전송된 것까지는 I/O 완료가 되었고, 버퍼가 꽉 차서 I/O 완료를 하지 못한 순간의 await 호출에 대해서만 dumpasync 결과로 나오게 됩니다.
0:016> !dumpasync
000001c136121748 00007ffe692993c8 ( ) System.Threading.Tasks.ValueTask+ValueTaskSourceAsTask
000001c136120528 00007ffe69ba8b78 (0) WpfApp1.MainWindow+<Window_Loaded>d__11 @ 7ffe69aba6c0
위의 출력에서 00007ff88ef0bb10, 00007ff88ef0dbb0은 Method Table을 의미하는데요, dumpasync가 GC Heap을 뒤져서 결과를 조합했다는 사실에서, 우리 역시 이 결과를 그대로 GC Heap에서 찾아 해당 인스턴스의 주소(000001c136121748, 000001c136120528)까지 찾을 수 있습니다.
0:016> !dumpheap -mt 00007ffe692993c8
Address MT Size
01c136121748 7ffe692993c8 80
Statistics:
MT Count TotalSize Class Name
7ffe692993c8 1 80 System.Threading.Tasks.ValueTask+ValueTaskSourceAsTask
Total 1 objects, 80 bytes
0:016> !dumpheap -mt 00007ffe69ba8b78
Address MT Size
01c136120528 7ffe69ba8b78 80
Statistics:
MT Count TotalSize Class Name
7ffe69ba8b78 1 80 System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>+AsyncStateMachineBox<WpfApp1.MainWindow+<Window_Loaded>d__11>
Total 1 objects, 80 bytes
위의 출력에서 재미있는 것은 "WpfApp1.MainWindow+<Window_Loaded>d__11" 항목의 MethodTable을 조회해 보면 "System.Runtime.CompilerServices.AsyncTaskMethodBuilder<System.Threading.Tasks.VoidTaskResult>+AsyncStateMachineBox<WpfApp1.MainWindow+<Window_Loaded>d__11>" 타입으로 나온다는 것입니다.
사실, 후자의 인스턴스로는 비동기 상태 머신의 state 값을 알아낼 수 없는데요, GC heap을 뒤져서 상탯값을 알고 싶다면 오히려 "WpfApp1.MainWindow+<Window_Loaded>d__11" 타입으로 시작해 추적을 해야만 합니다.
0:016> !name2ee *!WpfApp1.MainWindow+<Window_Loaded>d__11
Module: 00007ffe68da4000
Assembly: System.Private.CoreLib.dll
--------------------------------------
Module: 00007ffe68f8e0a0
Assembly: WpfApp1.dll
Token: 0000000002000005
MethodTable: 00007ffe69b8b608
EEClass: 00007ffe69b68918
Name: WpfApp1.MainWindow+<Window_Loaded>d__11
--------------------------------------
...[생략]...
0:016> !dumpheap -mt 00007ffe69b8b608
Address MT Size
01c13611f470 7ffe69b8b608 112
Statistics:
MT Count TotalSize Class Name
7ffe69b8b608 1 112 WpfApp1.MainWindow+<Window_Loaded>d__11
Total 1 objects, 112 bytes
0:016> !do 01c13611f470
Name: WpfApp1.MainWindow+<Window_Loaded>d__11
MethodTable: 00007ffe69b8b608
EEClass: 00007ffe69b68918
Tracked Type: false
Size: 112(0x70) bytes
File: C:\temp\WpfApp1\WpfApp1\bin\Debug\net8.0-windows\WpfApp1.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffe68e71188 4000008 40 System.Int32 1 instance 0 <>1__state
00007ffe69b8b560 4000009 50 ...VoidMethodBuilder 1 instance 000001c13611f4c0 <>t__builder
00007ffe68e35fa8 400000a 8 System.Object 0 instance 000001c13602dcd8 sender
00007ffe69615dc0 400000b 10 ...s.RoutedEventArgs 0 instance 000001c13611f440 e
00007ffe695f08d0 400000c 18 WpfApp1.MainWindow 0 instance 000001c13602dcd8 <>4__this
00007ffe69b8e3c0 400000d 20 ...Sockets.TcpClient 0 instance 000001c13611f778 <client>5__1
00007ffe69b8ca80 400000e 28 ...ets.NetworkStream 0 instance 000001c1361200f8 <ns>5__2
00007ffe68e71188 400000f 44 System.Int32 1 instance 65536 <length>5__3
00007ffe69b8cfc0 4000010 30 ...lationTokenSource 0 instance 000001c136120130 <ct>5__4
00007ffe68e71188 4000011 48 System.Int32 1 instance 99 <count>5__5
00007ffe692785f0 4000012 38 System.Byte[] 0 instance 000001c138c298c8 <buf>5__6
00007ffe6915e038 4000013 60 ...vices.TaskAwaiter 1 instance 000001c13611f4d0 <>u__1
바로 저런 지루한 작업을 dumpasync가 대체해 주고 있는 건데요, 실제로 저 상탯값을 확인하는 것도 dumpasync의 출력에 있었던 (이미 0이라고 보여주지만) 인스턴스 하나를 선택해 아래와 같이 명령을 내려주면 관련 Task와 상태 머신의 필드를 모두 확인할 수 있습니다.
0:016> !dumpasync --address 0x000001c136121748 --completed --fields
STACK 1
000001c136121748 00007ffe692993c8 ( ) System.Threading.Tasks.ValueTask+ValueTaskSourceAsTask
Address MT Type Value Name
000001c136121778 00007ffe68e71188 System.Int32 0 m_taskId
0000000000000000 00007ffe68ee9680 System.Delegate null m_action
0000000000000000 00007ffe68e35fa8 System.Object null m_stateObject
0000000000000000 00007ffe691507c0 ...Threading.Tasks.TaskScheduler null m_taskScheduler
000001c13612177c 00007ffe68e71188 System.Int32 33555456 m_stateFlags
000001c136121798 00007ffe68e35fa8 System.Object 000001c136121798 m_continuationObject
0000000000000000 00007ffe69150b28 ...sks.Task+ContingentProperties null m_contingentProperties
000001c136120160 00007ffe69295818 ...asks.Sources.IValueTaskSource 000001c136120160 _source
000001c136121788 00007ffe68e948b0 System.Int16 30 _token
000001c136120528 00007ffe69ba8b78 (0) WpfApp1.MainWindow+<Window_Loaded>d__11 @ 7ffe69aba6c0
Address MT Type Value Name
000001c13611f4b0 00007ffe68e71188 System.Int32 0 <>1__state
000001c13611f4c0 00007ffe69b8b560 ...rvices.AsyncVoidMethodBuilder 000001c13611f4c0 <>t__builder
000001c13602dcd8 00007ffe68e35fa8 System.Object 000001c13602dcd8 sender
000001c13611f440 00007ffe69615dc0 System.Windows.RoutedEventArgs 000001c13611f440 e
000001c13602dcd8 00007ffe695f08d0 WpfApp1.MainWindow 000001c13602dcd8 <>4__this
000001c13611f778 00007ffe69b8e3c0 System.Net.Sockets.TcpClient 000001c13611f778 <client>5__1
000001c1361200f8 00007ffe69b8ca80 System.Net.Sockets.NetworkStream 000001c1361200f8 <ns>5__2
000001c13611f4b4 00007ffe68e71188 System.Int32 65536 <length>5__3
000001c136120130 00007ffe69b8cfc0 ...ading.CancellationTokenSource 000001c136120130 <ct>5__4
000001c13611f4b8 00007ffe68e71188 System.Int32 99 <count>5__5
000001c138c298c8 00007ffe692785f0 System.Byte[] ...m.Byte[65536] <buf>5__6
000001c13611f4d0 00007ffe6915e038 ....CompilerServices.TaskAwaiter 000001c13611f4d0 <>u__1
어찌 보면 마이크로소프트 역시 스스로도 제공할 수밖에 없었던 명령어겠지만, dumpasync 명령어는 축복과도 같은 것입니다. ^^; (그래도 여전히 동기 시절만큼이나 직관적인 원인을 찾을 수는 없지만!)
이 정도면, 대충 dumpasync 명령어에 대해서는 이해하셨으리라 봅니다. ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]