Microsoft MVP성태의 닷넷 이야기
닷넷: 2225. Windbg - dumasync로 분석하는 async/await 호출 [링크 복사], [링크+제목 복사],
조회: 5032
글쓴 사람
정성태 (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)
13697정성태7/26/20243505닷넷: 2284. C# - async 메서드에서의 lock/Monitor.Enter/Exit 잠금 처리파일 다운로드1
13696정성태7/26/20243374오류 유형: 920. dotnet publish - error NETSDK1047: Assets file '...\obj\project.assets.json' doesn't have a target for '...'
13695정성태7/25/20243077닷넷: 2283. C# - Lock / Wait 상태에서도 STA COM 메서드 호출 처리파일 다운로드1
13694정성태7/25/20243579닷넷: 2282. C# - ASP.NET Core Web App의 Request 용량 상한값 (Kestrel, IIS)
13693정성태7/24/20243114개발 환경 구성: 717. Visual Studio - C# 프로젝트에서 레지스트리에 등록하지 않은 COM 개체 참조 및 사용 방법파일 다운로드1
13692정성태7/24/20243669디버깅 기술: 199. Windbg - 리눅스에서 뜬 닷넷 응용 프로그램 덤프 파일에 포함된 DLL의 Export Directory 탐색
13691정성태7/23/20243179디버깅 기술: 198. Windbg - 스레드의 Win32 Message Queue 정보 조회
13690정성태7/23/20242891오류 유형: 919. Visual C++ 리눅스 프로젝트 - error : ‘u8’ was not declared in this scope
13689정성태7/22/20243329디버깅 기술: 197. Windbg - PE 포맷의 Export Directory 탐색
13688정성태7/21/20243185닷넷: 2281. C# - Lock / Wait 상태에서도 일부 Win32 메시지 처리파일 다운로드1
13687정성태7/19/20243419닷넷: 2280. C# - PostThreadMessage로 보낸 메시지를 Windows Forms에서 수신하는 방법파일 다운로드1
13686정성태7/19/20243470오류 유형: 918. Visual Studio - ATL Simple Object 추가 시 error C2065: 'IDR_...': undeclared identifier
13685정성태7/19/20243559스크립트: 66. Windows 디렉터리 경로를 WSL의 /mnt 포맷으로 구하는 방법 - 두 번째 이야기
13684정성태7/19/20243274닷넷: 2279. C# - 문자열 보간식 사례
13683정성태7/18/20243435오류 유형: 917. ClrMD - Linux 환경의 .NET 5 덤프 분석 시 hang 현상
13682정성태7/18/20243326닷넷: 2278. WPF - 스레드에 종속되는 DependencyObject파일 다운로드1
13681정성태7/17/20243172닷넷: 2277. C# 13 - (2) 메서드 그룹의 자연 타입 개선 (메서드 추론 개선)파일 다운로드1
13680정성태7/16/20243111닷넷: 2276. C# - Method Group, Natural Type, function_type파일 다운로드1
13679정성태7/16/20242899Linux: 76. Linux - C++ (getaddrinfo 등을 담고 있는) libnss 정적 링크
13678정성태7/15/20242772VS.NET IDE: 191. Visual Studio 2022 - .NET 5 프로젝트를 Docker Support로 실행했을 때 오류
13677정성태7/15/20242634오류 유형: 916. MSBuild - CheckEolTargetFramework (warning NETSDK1138)
13676정성태7/14/20242789Linux: 75. gdb에서 glibc의 함수에 Breakpoint 걸기
13675정성태7/13/20243937C/C++: 166. C/C++ - DLL에서 template 함수를 export하는 방법 [1]파일 다운로드1
13674정성태7/13/20243181오류 유형: 915. Unhandled Exception: Microsoft.Diagnostics.NETCore.Client.ServerNotAvailableException: Unable to connect to Process
13673정성태7/11/20243335닷넷: 2275. C# 13 - (1) 신규 이스케이프 시퀀스 '\e'파일 다운로드1
13672정성태7/10/20243151닷넷: 2274. IIS - (프로세스 종료 없는) AppDomain Recycle
1  2  3  4  [5]  6  7  8  9  10  11  12  13  14  15  ...