PerfView와 dotnet-trace로 「느림」을 특정한다 ── .NET 성능 조사의 실무 입문

이전 글 「Windows 이벤트 로그·ETW 입문」에서는 ETW가 무엇인지와 EventSource로 고유 이벤트를 정의하는 곳까지 다루었고, PerfView에서의 분석은 「범위 밖」으로 두었습니다. 이 글은 그 후속입니다. 업무 앱이 「느리다」「CPU가 붙어 있다」「가끔 멈춘다」일 때, PerfView와 dotnet-trace로 원인 함수까지 특정하는 절차를 다룹니다.

참고로 이 글의 주제는 CPU·응답 시간 조사입니다. 메모리가 계속 늘어나는 문제의 원인 분리는 「.NET에서 GC 대기와 메모리 누수를 가려내기」, 크래시하는 문제는 「WinDbg + SOS로 크래시 덤프 읽기」에서 다루고 있습니다.

1. 먼저 결론

• 「느림」에는 두 종류가 있습니다. CPU를 다 써서 느린 경우(CPU bound)와, CPU는 한가한데 기다려서 느린 경우(블록)입니다. 전자는 CPU 샘플링, 후자는 ThreadTime(컨텍스트 스위치) 수집이 필요하며, 기본 CPU 수집만 봐서는 후자의 원인이 보이지 않습니다. ¹
• 고민되면 dotnet-trace부터 시작합니다. EventPipe 기반의 크로스 플랫폼 도구로, 대상 프로세스를 시작한 것과 같은 사용자라면 관리자 권한 없이 수집할 수 있습니다. ² 수집한 .nettrace는 PerfView나 Visual Studio에서 열 수 있습니다. ³
• PerfView가 필요해지는 것은 머신 전체·네이티브·블록 시간까지 보고 싶을 때입니다. ETW 기반이므로 커널 이벤트나 네이티브 코드 스택도 다룰 수 있습니다. 그 대신 ETW 세션을 시작하려면 관리자 권한이 필요합니다. ³
• CPU 샘플링은 기본값으로 1밀리초마다(프로세서마다)입니다. 1샘플=약 1ms의 CPU 시간으로 읽고, 기준으로 1,000샘플 이상(가능하면 5,000 정도)이 모인 뒤에 판단합니다. 샘플 수가 적을 때의 상위 함수는 우연일 수 있습니다. ¹
• 숫자 해석은 inclusive(자신+호출 대상)와 exclusive(자기 자신)의 구별이 모든 출발점입니다. exclusive가 큰 함수가 「실제로 CPU를 쓰는 곳」, inclusive가 큰 함수는 「그 아래 어딘가가 무거운 곳」입니다.
• 측정하기 전에, 무엇이 「느린지」를 하나의 조작으로 고정합니다. 「전반적으로 무겁다」인 채로 수집해도 읽을 수 없습니다. 「이 장표 출력에 40초가 걸린다」처럼 조작과 시간을 고정한 다음 수집합니다. 개선 전후 비교 측정의 사고방식은 「Windows에서 프로그램 버전별 속도를 올바르게 비교하는 방법」도 참고가 됩니다.

증상에서 들어가는 입구를 판단표로 정리합니다.

그림의 실선은 항상 성립하는 관계, 점선은 조건이 붙는 관계입니다(성립 조건은 상세 페이지의 관계별 설명에 적혀 있습니다). 관계 전체 목록(총 20건, 근거와 확신도 포함)과 주요 개념의 정의는 지식 맵 상세 페이지에 정리되어 있습니다(일본어). 데이터: JSON-LD / Turtle

2. 도구의 관계를 정리한다 ── ETW와 EventPipe

등장하는 도구는 많아 보이지만, 토대는 둘뿐입니다.

• ETW(Event Tracing for Windows): OS 전체를 관통하는 트레이스 기반입니다. 커널부터 앱까지 같은 시간축으로 기록할 수 있는 반면, 세션의 시작·중지에 관리자 권한이 필요하고 Windows 전용입니다. ³
• EventPipe: .NET 런타임에 내장된 트레이스 메커니즘입니다. 관리자 권한이 필요 없고 모든 OS에서 같이 동작하는 대신, 보이는 것은 매니지드 코드와 런타임 범위로 한정되며, 커널 이벤트나 네이티브 스택은 잡을 수 없습니다. ²

이 대응 관계를 파악하고 있으면, 「먼저 dotnet-trace로 가볍게 수집한다. 부족하면 PerfView로 ETW까지 수집한다」는 용도 구분이 자연스럽게 정해집니다.

3. 수집 전에 ── dotnet-counters로 경향을 10분 본다

갑자기 트레이스를 잡기보다, 먼저 dotnet-counters로 런타임의 주요 메트릭을 보는 편이 빠른 경우가 많습니다. ⁴

dotnet tool install --global dotnet-counters
dotnet-counters ps
dotnet-counters monitor --process-id <PID> --counters System.Runtime

여기서 보는 것은 CPU 사용률, GC 힙 크기와 GC 횟수, ThreadPool의 큐 길이·스레드 수, 예외 수입니다. 이 시점에서 「GC가 매초 여러 번 돈다」「ThreadPool 큐가 계속 늘어난다」 같은 경향이 보이면, 다음에 잡을 트레이스 종류(할당인지, 블록인지)를 좁힐 수 있습니다.

그렇다 해도, 처음 계측하는 사람에게는 「그 숫자가 이상인지」가 보이지 않습니다. 가장 확실한 기준은, 정상일 때의 자기 앱에서 같은 커맨드를 실행해 얻은 값입니다. 그것을 아직 갖추지 못한 단계에서 가늠하는 용도로, 실무에서 쓰는 보는 법을 정리합니다. ⁵

임계값 그 자체보다, 「시간에 따라 어떻게 움직이는가」를 보는 것이 핵심입니다. 부하에 따라 증감하고 상한에 닿는 값은 건전하고, 부하를 멈춰도 돌아가지 않는 값이 조사 대상이 됩니다. 메모리 계열 경향 읽는 법은 GC 대기와 메모리 누수 가려내는 글에서 자세히 적고 있습니다.

4. dotnet-trace로 트레이스를 잡는다

dotnet-trace는 EventPipe 기반 수집 도구입니다. ⁶ 설치와 기본 수집은 다음과 같습니다.

dotnet tool install --global dotnet-trace
dotnet-trace ps
dotnet-trace collect --process-id <PID> --duration 00:00:00:30

옵션을 아무것도 지정하지 않으면, 런타임의 주요 이벤트와 스레드 샘플링을 포함하는 기본 프로필 구성으로 수집됩니다. 예전에 있던 cpu-sampling이라는 이름의 프로필은 폐지되었고, 현재는 dotnet-common과 dotnet-sampled-thread-time의 조합이 기본입니다. ⁶ 용도에 따라 --profile gc-verbose(GC와 객체 할당의 샘플링)나 --profile gc-collect(GC 발생만 낮은 부하로 기록)도 고를 수 있습니다.

이전 글에서 만든 EventSource의 고유 프로바이더를 함께 수집하려면 --providers를 추가합니다.

dotnet-trace collect --process-id <PID> --providers KomuraSoft-OrderService

수집 결과는 .nettrace 파일이 됩니다. 여는 방법은 세 가지이며, Visual Studio나 PerfView로 열거나 speedscope 형식으로 변환해 브라우저에서 봅니다. ⁶

dotnet-trace convert trace.nettrace --format Speedscope

speedscope 형식은 speedscope.app에서 열리는 가벼운 프레임 그래프 표시로, 「어느 함수 아래에서 시간을 썼는지」를 직관적으로 보는 데 맞습니다.

어느 쪽으로 열지는, 그 결과를 누구에게 보여줄지로 정하면 고민이 줄어듭니다.

즉 PerfView는 조사용, speedscope는 공유용이라는 역할 나눔입니다. 함수 이름까지 특정하는 정밀 조사는 PerfView의 스택 뷰어가 더 강력하므로, 다음 장으로 갑니다.

5. PerfView로 CPU를 조사한다 ── 스택 뷰어 읽는 법

PerfView는 Microsoft가 무상 공개하는 성능 조사 도구로, GitHub 릴리스 페이지에서 PerfView.exe 하나만 다운로드하면 동작합니다(설치 불필요). ⁷

5.1 수집한다

GUI로 수집할 때의 흐름을, 화면의 어디를 건드리는지까지 풀어 쓰면 다음과 같습니다.

1. PerfView.exe를 관리자로 실행합니다(ETW 세션 시작에 관리자 권한이 필요합니다 ³)
2. 메뉴의 Collect > Collect(바로 가기는 Alt+C)를 고릅니다. 수집용 대화 상자가 열리고, 만들 데이터 파일 이름 입력을 요구합니다 ¹
3. 대화 상자의 체크박스로 수집 내용을 정합니다. 기본값 그대로면 CPU 샘플과 CLR의 주요 이벤트가 수집됩니다. 대기 시간까지 조사하려면 여기서 Thread Time 체크박스를 켭니다(6장) ¹
4. Start Collection 버튼을 누릅니다
5. 조사하고 싶은 조작을 재현합니다(여기가 계측 대상이 되므로, 불필요한 조작은 끼워 넣지 않습니다)
6. Stop Collection 버튼을 누릅니다. 수집 중지 후 데이터 머지와 심볼 해결이 돌고, 2에서 지정한 이름의 .etl.zip이 만들어집니다

같은 일을 커맨드라인으로 하면 다음 형태가 됩니다(이쪽도 관리자로 실행합니다 ³).

PerfView collect /nogui /acceptEULA /maxCollectSec:30

기본 수집은 모든 프로세서에서 1밀리초마다의 CPU 샘플(콜 스택 포함)과 CLR의 주요 이벤트를 포함합니다. ¹ 수집 중 오버헤드는 기본 구성에서 대략 수% 정도로 알려져 있습니다. ⁸

5.2 CPU Stacks를 읽는다

수집 결과(.etl.zip)를 열고 「CPU Stacks」에서 대상 프로세스를 고르면 스택 뷰어가 열립니다.

처음 보면 화면 요소가 많으므로, 어디에 무엇이 있는지를 먼저 대응시켜 둡니다. 스택 뷰어는 크게 「상단의 필터 입력란」과 「하단의 탭 전환 그리드」로 나뉩니다.

먼저 보는 것은 ByName 탭의 두 열입니다.

• Exc(exclusive): 그 함수 자신이 실행 중이던 샘플 수입니다. 실제로 CPU를 소비하는 곳입니다.
• Inc(inclusive): 그 함수와, 거기에서 호출된 모든 샘플 수 합계입니다. 그 아래 어딘가가 무겁다는 것을 나타냅니다.

읽는 방법의 기본은 Exc 상위부터 보고 「자기 코드인지, 런타임·라이브러리인지」를 가르는 것입니다. 자기 코드가 Exc 상위에 나와 있으면, 그 함수의 알고리즘이나 루프가 직접 대상입니다. System.String 계열이나 JSON 시리얼라이저가 Exc 상위라면, Callers 탭에서 그것을 Inc로 따라가 자기 코드의 어디에서 대량으로 호출하는지를 찾아냅니다.

또 하나 중요한 것이 샘플 수 자체의 확인입니다. CPU 샘플은 1ms 간격의 통계이므로, 샘플 수가 적으면 우연에 좌우됩니다. 기준으로 합계 1,000샘플 이상, 가능하면 5,000 정도를 모은 뒤에 판단하고, 부족하면 대상 조작을 반복 실행해 수집 시간을 늘립니다. ¹

참고로 자사 모듈의 함수 이름이 주소 표시가 되어 버리면, 심볼(PDB)이 해결되지 않은 것입니다. 빌드 산출물의 PDB를 손에 갖춰 두는 일이 곧 조사할 수 있느냐를 가릅니다. 이 이야기는 「PDB(프로그램 데이터베이스)란 무엇인가」에서 자세히 적고 있습니다.

6. 「CPU는 한가한데 느리다」 ── ThreadTime으로 블록 시간을 본다

실무의 「느림」의 절반 이상은 CPU가 아니라 대기입니다. 락 대기, DB·HTTP 응답 대기, 파일 I/O, Task.Result로 인한 데드락에 가까운 대기. 이런 문제는 CPU 샘플에 「애초에 CPU를 쓰지 않은 시간」으로 나타나지 않으므로, 기본 수집에서는 원인이 보이지 않습니다.

PerfView에서는 수집 시 Thread Time 옵션을 켜면 컨텍스트 스위치 이벤트가 추가로 기록되고, 각 스레드가 「CPU를 쓰던 시간」과 「블록하던 시간」을 함께 쫓을 수 있게 됩니다. ¹

활성화 방법은 GUI와 커맨드라인 두 가지이며, 어느 쪽이든 결과는 같습니다.

• GUI의 경우: 5.1의 절차 2에서 Collect > Collect(Alt+C) 대화 상자를 연 다음, Thread Time 체크박스를 켠 뒤에 Start Collection을 누릅니다. 공식 가이드도 「벽시계 시간 조사를 하려면 수집 대화 상자의 Thread Time 체크박스를 설정해야 한다」고 명시합니다. ¹ 여기를 놓치고 기본값 그대로 수집해 「블록 시간이 안 나온다」고 고민하는 것이 첫 관문입니다.
• 커맨드라인의 경우: /threadTime 스위치를 붙입니다.

PerfView collect /nogui /acceptEULA /threadTime /maxCollectSec:30

분석에서는 「Thread Time Stacks」 뷰를 엽니다. CPU Stacks와 같은 스택 뷰어지만, 샘플이 CPU 시간뿐 아니라 BLOCKED_TIME(블록하던 시간)도 포함하는 점이 다릅니다. 느린 조작의 시간 범위로 좁힌 다음, 처리를 맡던 스레드의 BLOCKED_TIME이 어느 스택(어느 대기)에 쌓여 있는지를 보면, 「합계 40초 중 35초는 이 HTTP 호출 대기였다」는 형태로 내역이 나옵니다.

UI가 멈추는 계열의 증상(조작하면 수 초 응답이 없음)도, 정체는 UI 스레드의 블록인 경우가 대부분입니다. ThreadTime으로 UI 스레드의 블록 대상을 특정한 다음, 근본 대책으로는 동기 대기를 비동기로 바꾸는 설계로 가져갑니다. 이 설계 쪽 정리는 「WPF/WinForms의 async와 UI 스레드를 한 장으로 정리」를 참고하십시오.

주의할 점으로, ThreadTime 수집은 컨텍스트 스위치마다 이벤트를 기록하므로 기본 수집보다 데이터양이 분명히 늘어납니다. 수집 시간은 짧게 나누고, 운영에서의 장시간 수집은 피하십시오.

7. EventSource와 조합한다 ── 「어느 구간이 느린가」를 업무 말로 자른다

CPU Stacks도 Thread Time도 프로세스 전체의 집계입니다. 「주문 처리 1건 안의 어디가 느린가」처럼 업무 처리 단위로 자르고 싶을 때는, 이전 글에서 다룬 EventSource의 Start/Stop 이벤트가 힘을 발휘합니다.

이전 글을 읽지 않았어도 이 장만으로 시험할 수 있도록, 추적 대상 프로바이더를 직접 만드는 최소 코드를 둡니다. 4장의 --providers KomuraSoft-OrderService는 이 Name을 가리킵니다.

using System.Diagnostics.Tracing;

// [EventSource(Name = ...)] 가 ETW/EventPipe에서 보이는 프로바이더 이름이 된다
[EventSource(Name = "KomuraSoft-OrderService")]
public sealed class OrderServiceEventSource : EventSource
{
    public static readonly OrderServiceEventSource Log = new OrderServiceEventSource();

    [Event(1, Level = EventLevel.Informational)]
    public void OrderProcessingStart(string orderId) => WriteEvent(1, orderId);

    [Event(2, Level = EventLevel.Informational)]
    public void OrderProcessingStop(string orderId) => WriteEvent(2, orderId);
}

호출 쪽은 계측하고 싶은 구간을 끼우기만 하면 됩니다.

OrderServiceEventSource.Log.OrderProcessingStart(orderId);
try
{
    ProcessOrder(orderId); // 계측하고 싶은 업무 처리
}
finally
{
    OrderServiceEventSource.Log.OrderProcessingStop(orderId);
}

메서드 이름을 ~Start / ~Stop으로 맞추고 이벤트 ID를 일련번호로 두면, PerfView의 Events 뷰에서 짝 구간으로 읽기 쉬워집니다. finally에서 반드시 Stop을 내는 것은, 예외로 빠진 회차가 「끝나지 않는 구간」으로 남지 않게 하기 위해서입니다. 이벤트 정의의 자세한 쓰는 법(인자 타입 제약, EventLevel과 Keywords의 용도 구분)은 이전 글을 참고하십시오.

이 계측이 있다는 전제로, 조사는 다음 순으로 진행합니다.

• 앱 쪽에서 OrderProcessingStart / OrderProcessingStop 같은 이벤트를 계측해 둡니다(위의 코드)
• PerfView의 「Events」 뷰에서 그 이벤트의 시각을 확인하고, 스택 뷰어의 시간 범위(Start/End 필터)를 그 구간으로 좁힙니다
• 좁힌 범위에서 CPU/블록 시간의 내역을 읽습니다

이렇게 하면 「느렸던 그 1회」만 대상으로 분석할 수 있어, 평상시 노이즈에 묻히지 않습니다. 고유 이벤트는 dotnet-trace에서도 같이 수집할 수 있으므로, 계측을 한 번 넣어 두면 개발 머신에서도 운영에서도 같은 조사 방법이 통합니다. 성능 조사는 도구를 다루는 실력보다 「앱 쪽에 관측점이 있는가」로 난이도가 정해진다는 것이 실무에서 느끼는 점입니다.

정리

• 「느림」을 CPU bound와 블록으로 가르는 것이 출발점입니다. 전자는 CPU 샘플링(1샘플≒1ms), 후자는 ThreadTime 수집이 아니면 나타나지 않습니다.
• 우선 관리자 권한 없이 쓸 수 있는 dotnet-trace, 머신 전체·네이티브·블록 시간이 필요하면 PerfView, 라는 용도 구분이 기본입니다. 수집한 .nettrace를 PerfView로 읽는 식으로 함께 쓰는 것도 정석입니다.
• 스택 뷰어는 exclusive와 inclusive의 구별이 읽는 법의 핵이며, 샘플 수가 충분한지를 항상 확인합니다.
• EventSource의 고유 이벤트로 업무 처리 구간을 자를 수 있게 해 두면, 조사 정밀도가 한 단계 올라갑니다.

合同会社小村ソフト에서는 「느리다」「멈춘다」「CPU가 붙어 있다」와 같은 Windows 업무 앱의 성능 문제 조사와, 계측하기 쉽게 하기 위한 계측·설계 상담을 다루고 있습니다. 재현 절차와 트레이스 파일이 있으면, 그다음 분석만 의뢰하는 것도 가능합니다.

관련 기사

• Windows 이벤트 로그·ETW 입문 ── 업무 앱의 로그를 OS 표준 구조 위에 올린다
• .NET에서 GC 대기와 메모리 누수를 가려내기 ── 늘어나는 메모리를 관측·비교·증명하는 실무 절차
• WinDbg + SOS로 크래시 덤프 읽기 ── 수집한 뒤의 실무 분석 입문
• Windows 크래시 덤프 수집 입문 - WER/ProcDump/WinDbg
• PDB(프로그램 데이터베이스)란 무엇인가 ── 디버그 정보·심볼·Source Link를 이해한다
• Windows에서 프로그램 버전별 속도를 올바르게 비교하는 방법
• WPF/WinForms의 async와 UI 스레드를 한 장으로 정리

관련 상담 영역

• 장애 조사·원인 분석
• Windows 앱 개발
• 기술 상담·설계 리뷰
• 문의

참고 링크

관련 기사

같은 태그를 공유하는 최신 기사입니다. 더 가까운 주제로 지식을 넓힐 수 있습니다.

관련 토픽

이 기사와 가까운 토픽 페이지입니다. 기사를 출발점 삼아 관련 서비스와 다른 기사로 이어집니다.

이 주제와 연결되는 서비스

이 기사는 다음 서비스 페이지로 이어집니다. 가까운 입구부터 확인해 주세요.

자주 묻는 질문

이 기사 주제에 대해 상담 시 자주 나오는 질문을 모았습니다.

PerfView와 dotnet-trace, 어느 쪽을 써야 합니까?

먼저 dotnet-trace부터 시도하는 것을 권합니다. 관리자 권한 없이 쓸 수 있고, 대상 프로세스만 골라 수집할 수 있으며, 조작도 커맨드 한 줄로 끝납니다. 한편 네이티브 코드 스택까지 보고 싶은 경우, 머신 전체 상황(다른 프로세스나 커널의 영향)까지 보고 싶은 경우, 블록 시간을 컨텍스트 스위치 단위로 쫓고 싶은 경우에는 ETW 기반 PerfView가 필요합니다. 수집한 .nettrace 파일을 PerfView로 열어 분석하는 식으로 함께 쓰는 것도 일상적으로 합니다.

Visual Studio 프로파일러와의 관계는 어떻게 됩니까?

개발 머신에서 재현되는 문제라면 Visual Studio의 CPU 사용률 도구나 메모리 도구가 더 손쉽고, 먼저 그쪽으로 충분합니다. PerfView나 dotnet-trace가 힘을 발휘하는 것은 Visual Studio를 넣을 수 없는 검증 머신·운영 머신에서 수집하는 장면, 수집과 분석을 다른 머신으로 나누고 싶은 장면, ETW 이벤트(고유 EventSource나 커널 이벤트)까지 포함해 보고 싶은 장면입니다. 참고로 Visual Studio는 dotnet-trace가 출력하는 .nettrace 파일을 열 수도 있습니다.

운영 서버에서 실행해도 괜찮습니까?

두 도구 모두 운영 환경에서의 짧은 수집을 염두에 두고 만들어졌지만, 무조건은 아닙니다. 수집 시간을 수십 초~수 분으로 나누고, 먼저 검증 환경에서 같은 커맨드를 시험해 오버헤드와 파일 크기를 확인하고, 디스크 여유 용량을 확인하는 절차를 밟으십시오. 특히 ThreadTime(컨텍스트 스위치) 수집이나 할당 트레이스는 이벤트 양이 많아 파일이 빠르게 커집니다. 또한 트레이스에는 커맨드라인 인수 등의 정보가 포함되므로, 수집한 파일의 취급에도 주의가 필요합니다.

WPR/WPA와는 어떻게 나눠 씁니까?

WPR(Windows Performance Recorder)과 WPA(Windows Performance Analyzer)는 같은 ETW를 바탕으로 한, 보다 OS에 가까운 조사 도구입니다. 디스크 I/O·전원·시작 시간 등 OS 전체의 상세 분석에서는 WPR/WPA가 강하고, .NET 앱의 CPU·GC·블록 시간 조사에서는 매니지드 코드 표시에 최적화된 PerfView가 읽기 쉽습니다. 업무 앱 조사가 목적이라면 PerfView와 dotnet-trace로 대부분 충분합니다.

저자 프로필

기사 저자의 프로필 페이지입니다.

Go Komura

합동회사 코무라소프트 대표

Windows 소프트웨어 개발, 기술 상담, 장애 조사를 중심으로 재현이 어려운 장애 조사와 기존 자산이 남아 있는 프로젝트에 강점이 있습니다.