Microsoft MVP성태의 닷넷 이야기
닷넷: 2225. Windbg - dumasync로 분석하는 async/await 호출 [링크 복사], [링크+제목 복사],
조회: 6042
글쓴 사람
정성태 (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)
13841정성태12/11/2024244오류 유형: 937. error MSB4044: The "ValidateValidArchitecture" task was not given a value for the required parameter "RemoteTarget"
13840정성태12/11/2024221오류 유형: 936. msbuild - Your project file doesn't list 'win' as a "RuntimeIdentifier"
13839정성태12/11/2024236오류 유형: 936. msbuild - error CS1617: Invalid option '12.0' for /langversion. Use '/langversion:?' to list supported values.
13838정성태12/4/20241053오류 유형: 935. Windbg - Breakpoint 0's offset expression evaluation failed.
13837정성태12/3/20241070디버깅 기술: 204. Windbg - 윈도우 핸들 테이블 (3) - Windows 10 이상인 경우
13836정성태12/3/20241101디버깅 기술: 203. Windbg - x64 가상 주소를 물리 주소로 변환 (페이지 크기가 2MB인 경우)
13835정성태12/2/20241076오류 유형: 934. Azure - rm: cannot remove '...': Directory not empty
13834정성태11/29/20241193Windows: 275. C# - CUI 애플리케이션과 Console 윈도우 (Windows 10 미만의 Classic Console 모드인 경우)파일 다운로드1
13833정성태11/29/20241222개발 환경 구성: 737. Azure Web App에서 Scale-out으로 늘어난 리눅스 인스턴스에 SSH 접속하는 방법
13832정성태11/27/20241218Windows: 274. Windows 7부터 도입한 conhost.exe
13831정성태11/27/20241018Linux: 111. eBPF - BPF_MAP_TYPE_PERF_EVENT_ARRAY, BPF_MAP_TYPE_RINGBUF에 대한 다양한 용어들
13830정성태11/25/20241105개발 환경 구성: 736. 파이썬 웹 앱을 Azure App Service에 배포하기
13829정성태11/25/20241046스크립트: 67. 파이썬 - Windows 버전에서 함께 설치되는 py.exe
13828정성태11/25/20241060개발 환경 구성: 735. Azure - 압축 파일을 이용한 web app 배포 시 디렉터리 구분이 안 되는 문제파일 다운로드1
13827정성태11/25/20241145Windows: 273. Windows 환경의 파일 압축 방법 (tar, Compress-Archive)
13826정성태11/21/20241248닷넷: 2313. C# - (비밀번호 등의) Console로부터 입력받을 때 문자열 출력 숨기기(echo 끄기)파일 다운로드1
13825정성태11/21/20241191Linux: 110. eBPF / bpf2go - BPF_RINGBUF_OUTPUT / BPF_MAP_TYPE_RINGBUF 사용법
13824정성태11/20/20241160Linux: 109. eBPF / bpf2go - BPF_PERF_OUTPUT / BPF_MAP_TYPE_PERF_EVENT_ARRAY 사용법
13823정성태11/20/20241120개발 환경 구성: 734. Ubuntu에 docker, kubernetes (k3s) 설치
13822정성태11/20/20241084개발 환경 구성: 733. Windbg - VirtualBox VM의 커널 디버거 연결 시 COM 포트가 없는 경우
13821정성태11/18/20241239Linux: 108. Linux와 Windows의 프로세스/스레드 ID 관리 방식
13820정성태11/18/20241255VS.NET IDE: 195. Visual C++ - C# 프로젝트처럼 CopyToOutputDirectory 항목을 추가하는 방법
13819정성태11/15/20241272Linux: 107. eBPF - libbpf CO-RE의 CONFIG_DEBUG_INFO_BTF 빌드 여부에 대한 의존성
13818정성태11/15/20241388Windows: 272. Windows 11 24H2 - sudo 추가
13817정성태11/14/20241232Linux: 106. eBPF / bpf2go - (BPF_MAP_TYPE_HASH) Map을 이용한 전역 변수 구현
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...