Microsoft MVP성태의 닷넷 이야기
닷넷: 2225. Windbg - dumasync로 분석하는 async/await 호출 [링크 복사], [링크+제목 복사],
조회: 2599
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일
 

(시리즈 글이 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 - 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 명령어에 대해서는 이해하셨으리라 봅니다. ^^





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







[최초 등록일: ]
[최종 수정일: 3/5/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)
13597정성태4/15/20242044닷넷: 2239. C# - WAV 파일의 PCM 데이터 생성 및 출력파일 다운로드1
13596정성태4/14/20242355닷넷: 2238. C# - WAV 기본 파일 포맷파일 다운로드1
13595정성태4/13/20242310닷넷: 2237. C# - Audio 장치 열기 (Windows Multimedia, NAudio)파일 다운로드1
13594정성태4/12/20242324닷넷: 2236. C# - Audio 장치 열람 (Windows Multimedia, NAudio)파일 다운로드1
13593정성태4/8/20242383닷넷: 2235. MSBuild - AccelerateBuildsInVisualStudio 옵션
13592정성태4/2/20243089C/C++: 165. CLion으로 만든 Rust Win32 DLL을 C#과 연동 [1]
13591정성태4/2/20242216닷넷: 2234. C# - WPF 응용 프로그램에 Blazor App 통합파일 다운로드1
13590정성태3/31/20242100Linux: 70. Python - uwsgi 응용 프로그램이 k8s 환경에서 OOM 발생하는 문제
13589정성태3/29/20242300닷넷: 2233. C# - 프로세스 CPU 사용량을 나타내는 성능 카운터와 Win32 API파일 다운로드1
13588정성태3/28/20242796닷넷: 2232. C# - Unity + 닷넷 App(WinForms/WPF) 간의 Named Pipe 통신 [2]파일 다운로드1
13587정성태3/27/20242335오류 유형: 900. Windows Update 오류 - 8024402C, 80070643
13586정성태3/27/20243488Windows: 263. Windows - 복구 파티션(Recovery Partition) 용량을 늘리는 방법
13585정성태3/26/20242535Windows: 262. PerformanceCounter의 InstanceName에 pid를 추가한 "Process V2"
13584정성태3/26/20242628개발 환경 구성: 708. Unity3D - C# Windows Forms / WPF Application에 통합하는 방법 [4]파일 다운로드1
13583정성태3/25/20242488Windows: 261. CPU Utilization이 100% 넘는 경우를 성능 카운터로 확인하는 방법
13582정성태3/19/20242633Windows: 260. CPU 사용률을 나타내는 2가지 수치 - 사용량(Usage)과 활용률(Utilization)파일 다운로드1
13581정성태3/18/20242642개발 환경 구성: 707. 빌드한 Unity3D 프로그램을 C++ Windows Application에 통합하는 방법
13580정성태3/15/20242313닷넷: 2231. C# - ReceiveTimeout, SendTimeout이 적용되지 않는 Socket await 비동기 호출파일 다운로드1
13579정성태3/13/20242753오류 유형: 899. HTTP Error 500.32 - ANCM Failed to Load dll
13578정성태3/11/20243037닷넷: 2230. C# - 덮어쓰기 가능한 환형 큐 (Circular queue)파일 다운로드1
13577정성태3/9/20243339닷넷: 2229. C# - 닷넷을 위한 난독화 도구 소개 (예: ConfuserEx)
13576정성태3/8/20242626닷넷: 2228. .NET Profiler - IMetaDataEmit2::DefineMethodSpec 사용법
13575정성태3/7/20242880닷넷: 2227. 최신 C# 문법을 .NET Framework 프로젝트에 쓸 수 있을까요?
13574정성태3/6/20242715닷넷: 2226. C# - "Docker Desktop for Windows" Container 환경에서의 IPv6 DualMode 소켓
13573정성태3/5/20242599닷넷: 2225. Windbg - dumasync로 분석하는 async/await 호출
13572정성태3/4/20242848닷넷: 2224. C# - WPF의 Dispatcher Queue로 알아보는 await 호출의 hang 현상파일 다운로드1
1  2  [3]  4  5  6  7  8  9  10  11  12  13  14  15  ...