동시성 버그는 fmt.Println만으로는 원인을 찾기 어렵다. goroutine이 언제 실행되고 언제 블로킹되는지, 채널을 통해 데이터가 어떤 순서로 흐르는지를 눈으로 확인할 수 있다면 디버깅이 훨씬 쉬워진다. 이 글에서는 Go가 제공하는 동시성 시각화/분석 도구들을 실습과 함께 정리한다.

1. 왜 동시성 코드를 시각화해야 하는가

1.1 fmt.Println 디버깅의 한계

순차 코드에서는 로그를 한 줄씩 추가하면 실행 흐름을 추적할 수 있다. 하지만 동시성 코드에서는 이 방법이 통하지 않는 경우가 많다.

• 출력 순서가 보장되지 않는다: goroutine의 실행 순서는 런타임 스케줄러에 의해 결정되므로, 로그 출력 순서가 실제 발생 순서와 다를 수 있다.
• Heisenbug: fmt.Println을 추가하면 내부적으로 동기화가 일어나 실행 타이밍이 바뀌면서 버그가 사라지는 현상(하이젠버그)이 발생할 수 있다.
• 인과관계 파악 불가: 로그만으로는 "goroutine A가 채널에 값을 보낸 뒤 goroutine B가 받았다"는 인과관계를 정확히 파악하기 어렵다.

1.2 도구별 역할 비교

도구	유형	용도	오버헤드
go tool trace	내장	전체 타임라인, GC, blocking 분석	1-2% CPU (Go 1.21+)
GODEBUG=schedtrace	내장	스케줄러 상태 빠른 확인	거의 없음
gotraceui	서드파티	대용량 trace, 상세 goroutine 분석	없음 (뷰어)
divan/gotrace	서드파티	교육용 3D 시각화	높음
Flight Recorder	내장 (Go 1.25)	프로덕션 이상 징후 캡처	메모리 2-10 MB/s

2. go tool trace 기본 사용법

runtime/trace 패키지는 Go 프로그램의 실행 이벤트(goroutine 생성/종료, 스케줄링, GC, syscall 등)를 수집한다. 수집된 데이터는 go tool trace로 브라우저에서 시각화할 수 있다.

2.1 trace 수집 3가지 방법

방법 1: 코드에 직접 삽입

trace.Start와 trace.Stop을 사용하여 원하는 구간만 정밀하게 수집한다.

func TestBasicTrace_Start_Stop(t *testing.T) {
    // tmp 폴더에 영속 저장 (t.TempDir()과 달리 테스트 후에도 남아 go tool trace로 분석 가능)
    err := os.MkdirAll("tmp", 0o755)
    assert.NoError(t, err)

    f, err := os.Create("tmp/trace_basic.out")
    assert.NoError(t, err)
    defer func() { _ = f.Close() }()

    // trace 수집 시작
    err = rttrace.Start(f)
    assert.NoError(t, err)

    // 여러 goroutine에서 동시 작업 수행
    var wg sync.WaitGroup
    for i := range 5 {
        wg.Add(1)
        go func() {
            defer wg.Done()
            sum := 0
            for range 1_000_000 {
                sum++
            }
            t.Logf("goroutine %d: sum=%d", i, sum)
        }()
    }
    wg.Wait()

    // trace 수집 중지
    rttrace.Stop()

    // trace 파일이 생성되었는지 검증
    info, err := f.Stat()
    assert.NoError(t, err)
    assert.Positive(t, info.Size(), "trace 파일이 비어있지 않아야 한다")
}

import rttrace "runtime/trace"로 alias를 사용하면 표준 라이브러리의 runtime/trace와 패키지명 충돌을 피할 수 있다.

방법 2: go test -trace 플래그

코드를 수정하지 않고 테스트 실행 중 trace를 수집할 수 있다.

go test -v -trace=trace.out ./golang/concurrency/trace/...
go tool trace trace.out

방법 3: HTTP endpoint (net/http/pprof)

운영 중인 서버에서 HTTP 요청으로 trace를 수집한다.

import _ "net/http/pprof"

// 기본 HTTP 서버에 pprof 핸들러가 자동 등록됨
// curl -o trace.out http://localhost:6060/debug/pprof/trace?seconds=5

2.2 trace 분석

수집된 trace 파일은 다음 명령으로 브라우저에서 열 수 있다.

go tool trace tmp/trace_basic.out

명령을 실행하면 로컬 웹 서버(예: http://127.0.0.1:52022)가 뜨고, 브라우저에 여러 분석 뷰 링크가 표시된다. 각 뷰의 실제 화면과 해석은 다음 섹션에서 자세히 다룬다.

3. go tool trace 핵심 뷰 해석

이 섹션의 화면은 앞의 TestBasicTrace_Start_Stop(goroutine 5개가 각각 100만 번 카운트하는 CPU 바운드 작업) trace를 실제로 열어본 것이다. 각 뷰를 어떻게 읽어야 하는지를 이 예제 기준으로 살펴본다.

먼저 알아둘 것 — Go 스케줄러의 GMP 모델

trace 뷰를 읽으려면 Go 런타임 스케줄러를 구성하는 세 요소를 알아야 한다. Go는 수천 개의 goroutine을 소수의 OS 스레드 위에서 돌리기 위해 다음 세 가지를 조합한다.

약자	정식 명칭	정체
G	Goroutine	Go가 관리하는 경량 실행 단위(go func()로 생성). 처리할 작업
M	Machine	실제 OS 스레드. 코드를 물리적으로 실행하는 일꾼
P	Processor	논리 프로세서. G를 M에 배분하는 스케줄링 컨텍스트(로컬 실행 큐 보유). 일감을 나눠주는 작업대

goroutine(G)이 실행되려면 M이 P를 잡고, P의 로컬 큐에서 G를 꺼내 M 위에서 실행한다. P의 개수는 GOMAXPROCS(기본값은 CPU 코어 수)로 정해지며, 이것이 동시에 실제 코드를 실행할 수 있는 goroutine 수의 상한이 된다. 이 G/M/P 개념은 이후 5장의 schedtrace/scheddetail 출력 해석에서도 그대로 쓰인다.

3.1 View Trace (타임라인)

타임라인 뷰는 시간 축을 따라 프로그램의 모든 이벤트를 보여주는 핵심 뷰다. 상단에는 전체 추이 그래프가, 하단에는 실행 주체별 막대가 표시된다.

• Heap: 메모리 할당 패턴. GC 후 힙이 줄어드는 패턴이 보인다
• Goroutines: running(실행 중) vs runnable(실행 가능하지만 대기 중) 개수. runnable이 높으면 P가 부족하거나 스케줄링 경합이 있다는 의미
• OS Threads: 활성 스레드 수. syscall로 블로킹된 스레드가 많으면 네트워크/디스크 I/O 병목 가능
• PROCS: 각 P(Processor)별 goroutine 실행 상황. GC STW(Stop-The-World) 이벤트도 여기서 확인 가능

타임라인 하단은 P(논리 프로세서) 기준 또는 OS 스레드(M) 기준으로 볼 수 있다.

View by proc — P별 타임라인

• 5개의 TestBasicTrace_Start_Stop.func2 막대가 서로 다른 P에 분산되어 거의 동시에 실행됐다 → 멀티코어 병렬성이 잘 활용되고 있다는 의미다.
• 막대가 중간에 끊기지 않고 짧게 끝나는 것은, 카운트 루프가 블로킹 없이 CPU만 사용하는 작업이기 때문이다.
• 특정 P에만 막대가 몰리거나 막대 사이 빈 구간(idle)이 길면 부하 불균형이나 스케줄링 경합을 의심한다.

View by thread — OS 스레드(M)별 타임라인

• 같은 실행을 P가 아닌 OS 스레드(M) 기준으로 본 화면이다(Thread 6171537408 등). syscall로 표시된 구간은 해당 스레드가 시스템 콜에 묶여 있던 시간이다.
• syscall 구간이 많고 길면 네트워크/디스크 I/O 병목을, 스레드(M) 개수가 급증하면 블로킹 syscall 때문에 런타임이 스레드를 추가로 만들고 있다는 신호로 본다. 이번 예제는 순수 CPU 작업이라 syscall 구간이 거의 없다.

3.2 Goroutine Analysis

goroutine을 유형별로 그룹화하여 시간 분포를 보여준다. 먼저 시작 위치별 요약 표가 나오고, 그룹을 클릭하면 goroutine별 상세 분해로 이어진다.

요약 — 시작 위치별 그룹

• goroutine을 시작 위치(start location) 기준으로 묶어 개수(Count)와 총 실행 시간을 보여준다.
• 이번 예제에서는 ...TestBasicTrace_Start_Stop.func2가 Count 5, 총 2.14ms로 가장 큰 비중을 차지한다 → 우리가 띄운 5개 워커가 작업 대부분을 수행했다는 뜻이다. 나머지 testing.tRunner, runtime.*는 테스트 하네스와 Go 런타임이 만든 보조 goroutine이다.
• 어떤 함수에서 시작된 goroutine이 시간을 많이 쓰는지로 병목 후보를 좁힌다.

상세 — 그룹별 시간 분해

요약 표에서 그룹을 클릭하면 goroutine별로 시간이 어디에 쓰였는지 항목별로 분해해서 보여준다. 이번 그룹은 실행 시간이 전체 프로그램의 **86.20%**를 차지한다.

• Execution: 실제 CPU 실행 시간 (여기선 86%로 압도적 → 전형적인 CPU 바운드 작업)
• Network wait: 네트워크 I/O 대기
• Sync block: 뮤텍스, 채널 등 동기화 대기 (여기선 0에 가까움 — WaitGroup 외 경합 없음)
• Blocking syscall: 시스템 콜 블로킹
• Scheduler wait: 실행 가능하지만 P를 기다리는 시간 (값이 크면 P 부족이나 스케줄링 경합)

Execution 비중이 높으면 연산/알고리즘 최적화 대상, Sync block이 크면 락 설계 재검토, Scheduler wait가 크면 GOMAXPROCS나 goroutine 수 조정을 고려한다.

3.3 Blocking Profiles

Network / Synchronization / Syscall 별 blocking 프로파일을 pprof 스타일 그래프로 보여준다. 어떤 함수에서 블로킹이 가장 많이 발생하는지 콜 그래프 형태로 확인할 수 있다.

3.4 Scheduler Latency Profile

goroutine이 runnable 상태가 된 후 실제로 P에서 실행될 때까지의 대기 시간 분포를 보여준다. 스케줄러 latency가 높다면 GOMAXPROCS를 늘리거나 goroutine 수를 줄이는 것을 고려해야 한다.

4. User-Defined Tasks와 Regions

기본 trace만으로도 goroutine 수준의 분석이 가능하지만, 비즈니스 로직 수준의 분석을 위해서는 Task, Region, Log를 활용해야 한다. 본격적으로 들어가기 전에 세 용어를 간단히 정리하면 다음과 같다.

• Task: 여러 goroutine에 걸친 논리적 작업 단위. "주문 처리"처럼 하나의 흐름을 묶는 컨테이너다. (trace.NewTask)
• Region: 단일 goroutine 내에서 특정 구간의 실행 시간을 측정하는 단위. Task 안에서 "DB 조회", "검증" 같은 세부 구간을 나눈다. (trace.WithRegion / trace.StartRegion)
• Log: trace 타임라인의 특정 시점에 key-value 형태로 이벤트를 남기는 마킹. 측정이 아니라 "이 순간 무슨 일이 있었는지"를 기록한다. (trace.Log)

세 가지를 한 문장으로 요약하면, Task는 작업을 묶고, Region은 구간을 재고, Log는 순간을 표시한다.

4.1 Task: 논리적 작업 단위

Task는 여러 goroutine에 걸친 논리적 작업을 하나로 묶어준다. 예를 들어 "주문 처리"라는 Task 안에 DB 조회, 결제, 알림 전송이 각각 다른 goroutine에서 실행되더라도 하나의 Task로 추적할 수 있다.

ctx, task := rttrace.NewTask(ctx, "order-process")
defer task.End()
rttrace.Log(ctx, "orderID", "ORD-0001")

go tool trace에서 Task별 latency 히스토그램을 확인할 수 있어, 어떤 종류의 작업이 느린지 쉽게 파악할 수 있다.

4.2 Region: 구간 측정

Region은 단일 goroutine 내에서 특정 구간의 시간을 측정한다. 두 가지 방식으로 사용할 수 있다.

WithRegion (클로저 방식)

rttrace.WithRegion(ctx, "fetch-data", func() {
    // 이 구간의 실행 시간이 trace에 기록된다
    time.Sleep(2 * time.Millisecond)
    result = 42
})

StartRegion/End (수동 방식)

클로저 바깥에서도 Region을 제어할 수 있고, 중첩(nested)도 가능하다.

region := rttrace.StartRegion(ctx, "validation")
// 작업 수행
region.End()

4.3 Log: 이벤트 마킹

trace.Log는 trace 타임라인에 특정 시점의 상태를 기록한다.

rttrace.Log(ctx, "request", "GET /api/users")
rttrace.Log(ctx, "cache", "HIT user-list")

4.4 Task/Region/Log 동작 흐름

sequenceDiagram
    participant Main as Main Goroutine
    participant W1 as Worker-1
    participant W2 as Worker-2

    Main->>Main: NewTask("order-process")
    Main->>W1: go fetchData(ctx)
    Main->>W2: go sendNotification(ctx)

    activate W1
    W1->>W1: WithRegion("fetch-data")
    W1->>W1: Log("db-query", "SELECT ...")
    W1->>W1: WithRegion("transform-data")
    deactivate W1

    activate W2
    W2->>W2: WithRegion("send-email")
    W2->>W2: Log("status", "sent")
    deactivate W2

    Main->>Main: task.End()

5. GODEBUG 스케줄러 트레이싱

go tool trace는 정밀한 분석이 가능하지만, 때로는 스케줄러의 매크로 상태를 빠르게 확인하고 싶을 때가 있다. 이때 GODEBUG=schedtrace를 사용한다.

5.1 기본 사용법

GODEBUG=schedtrace=1000 ./myapp

1초(1000ms)마다 스케줄러 상태가 stderr로 출력된다.

SCHED 0ms: gomaxprocs=12 idleprocs=10 threads=3 spinningthreads=1
  needspinning=0 idlethreads=0 runqueue=0
  [0 0 0 0 0 0 0 0 0 0 0 0]

5.2 출력 필드 해석

필드	의미
gomaxprocs	GOMAXPROCS 값 (P의 수)
idleprocs	유휴 P의 수
threads	OS 스레드(M) 수
spinningthreads	실행할 goroutine을 찾고 있는 M 수
runqueue	글로벌 실행 큐의 goroutine 수
[...]	각 P의 로컬 실행 큐 goroutine 수

5.3 scheddetail=1 상세 출력

GODEBUG=schedtrace=1000,scheddetail=1 ./myapp

P, M, G 각각의 상세 상태가 출력된다.

• P 라인: status(idle/running/syscall), schedtick, syscalltick, 로컬 큐 크기
• M 라인: P 바인딩 상태, spinning 여부, blocked 여부
• G 라인: goroutine 상태, 대기 이유

5.4 Goroutine 상태 코드

코드	이름	의미
0	_Gidle	생성 직후, 아직 초기화 안 됨
1	_Grunnable	실행 가능, 큐에서 대기 중
2	_Grunning	M에서 실행 중
3	_Gsyscall	시스템 콜 실행 중
4	_Gwaiting	채널, 뮤텍스 등에서 블로킹

5.5 subprocess를 이용한 테스트

GODEBUG 환경변수는 프로세스 시작 시에만 적용되므로, 테스트에서는 os/exec로 subprocess를 실행하여 검증한다.

func TestSchedtrace_GODEBUG_출력_파싱(t *testing.T) {
    if os.Getenv("SCHEDTRACE_HELPER") == "1" {
        // helper 프로세스: goroutine을 생성하여 스케줄러 활동 유발
        var wg sync.WaitGroup
        for range 50 {
            wg.Add(1)
            go func() {
                defer wg.Done()
                sum := 0
                for range 100_000 {
                    sum++
                }
            }()
        }
        wg.Wait()
        return
    }

    // 메인 테스트: subprocess로 helper 실행
    cmd := exec.Command(os.Args[0],
        "-test.run=TestSchedtrace_GODEBUG_출력_파싱",
        "-test.v",
    )
    cmd.Env = append(os.Environ(),
        "SCHEDTRACE_HELPER=1",
        "GODEBUG=schedtrace=100",
    )

    output, err := cmd.CombinedOutput()
    outputStr := string(output)

    assert.NoError(t, err, "subprocess 실행 실패")
    assert.Contains(t, outputStr, "SCHED", "schedtrace 출력이 있어야 한다")
    assert.Contains(t, outputStr, "gomaxprocs=", "gomaxprocs 필드가 있어야 한다")
}

SCHEDTRACE_HELPER=1 환경변수가 없으면 t.Skip() 대신 자연스럽게 subprocess 실행 경로로 분기하는 패턴이다. helper 프로세스는 SCHEDTRACE_HELPER=1이 설정되어 있을 때만 실제 워크로드를 수행한다.

6. Flight Recorder (Go 1.25)

6.1 Go trace 발전사

Go의 execution trace는 지속적으로 개선되어 왔다.

버전	변경사항
Go 1.21	trace 오버헤드 10-20% → **1-2%**로 대폭 감소
Go 1.22	새 trace 포맷 도입 (파티셔닝, 스트리밍, per-M 배치)
Go 1.25	runtime/trace.FlightRecorder 정식 포함

6.2 FlightRecorder란

FlightRecorder는 링 버퍼 방식으로 항상 trace를 수집하다가, 이상 징후 발생 시 스냅샷을 저장하는 "블랙박스 레코더"다. 비행기의 블랙박스처럼, 문제가 발생한 직전 상황을 사후에 분석할 수 있다.

flowchart LR
    A[FlightRecorder 시작] --> B[링 버퍼에 trace 수집]
    B --> C{이상 징후 감지?}
    C -- 아니오 --> B
    C -- 예 --> D[WriteTo로 스냅샷 저장]
    D --> E[go tool trace로 분석]
    D --> B

6.3 기본 API

fr := rttrace.NewFlightRecorder(rttrace.FlightRecorderConfig{
    MinAge:   200 * time.Millisecond,  // 최소 보관 시간
    MaxBytes: 1 << 20,                 // 최대 1 MiB
})

fr.Start()
defer fr.Stop()

// 이상 징후 발생 시 스냅샷 저장
if latency > threshold {
    var buf bytes.Buffer
    fr.WriteTo(&buf)
}

• MinAge: 링 버퍼에 최소 이 시간만큼의 trace 데이터를 유지
• MaxBytes: 링 버퍼의 최대 크기. 초과 시 오래된 데이터부터 삭제

6.4 실전 예제: HTTP 서버 latency 감지

다음은 HTTP 서버에서 응답 시간이 threshold를 초과할 때 자동으로 FlightRecorder 스냅샷을 캡처하는 예제다.

func TestFlightRecorder_HTTP서버_Latency_감지(t *testing.T) {
    const latencyThreshold = 50 * time.Millisecond

    fr := rttrace.NewFlightRecorder(rttrace.FlightRecorderConfig{
        MinAge:   200 * time.Millisecond,
        MaxBytes: 1 << 20,
    })

    err := fr.Start()
    assert.NoError(t, err)
    defer fr.Stop()

    // 가변 응답 시간 서버
    requestCount := 0
    var mu sync.Mutex
    server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        mu.Lock()
        count := requestCount
        requestCount++
        mu.Unlock()

        // 5번째 요청마다 느린 응답 시뮬레이션
        if count%5 == 4 {
            time.Sleep(80 * time.Millisecond)
        } else {
            time.Sleep(5 * time.Millisecond)
        }
        fmt.Fprintf(w, "request-%d", count)
    }))
    defer server.Close()

    // 클라이언트: latency 초과 시 스냅샷 캡처
    var snapshots []int64
    client := server.Client()

    for i := range 10 {
        start := time.Now()
        resp, err := client.Get(server.URL)
        assert.NoError(t, err)
        io.Copy(io.Discard, resp.Body)
        resp.Body.Close()

        elapsed := time.Since(start)
        if elapsed > latencyThreshold {
            var buf bytes.Buffer
            n, _ := fr.WriteTo(&buf)
            snapshots = append(snapshots, n)
            t.Logf("스냅샷 캡처\! (크기: %d bytes, latency: %v)", n, elapsed)
        }
    }

    assert.NotEmpty(t, snapshots, "latency 초과 시 스냅샷이 캡처되어야 한다")
}

프로덕션 환경에서는 fr.WriteTo의 결과를 파일로 저장하거나 객체 스토리지에 업로드하여, 나중에 go tool trace로 분석할 수 있다.

6.5 MinAge/MaxBytes 설정 가이드

시나리오	MinAge	MaxBytes	설명
빠른 요청 분석	200ms	1 MiB	단일 요청의 상세 trace
배치 작업 분석	5s	10 MiB	긴 작업의 전체 흐름 추적
메모리 제한 환경	100ms	512 KiB	최소한의 메모리 사용

7. 서드파티 시각화 도구

7.1 gotraceui (dominikh/gotraceui)

go tool trace의 웹 기반 뷰어는 Chrome 의존성이 있고, 대용량 trace에서 느릴 수 있다. gotraceui는 이를 대체하는 네이티브 GUI 뷰어다.

장점:

• Chrome 의존성 없음 (Gio 프레임워크 기반 네이티브 앱)
• 대용량 trace 효율적 처리
• per-goroutine 타임라인, 히트맵, 플레임 그래프
• CPU 샘플 오버레이

설치 및 사용:

go install honnef.co/go/gotraceui/cmd/gotraceui@latest
gotraceui trace.out

실제로 worker pool trace를 열어보면 Processor별/goroutine별 타임라인과 실행 상태(sync, blocked, inactive)가 한눈에 들어온다.

Goroutines 탭에서는 goroutine별 시작/종료 시각과 실행 시간을 표로 확인할 수 있다.

메모리 요구사항: trace 파일 크기의 약 30배. 100MB trace → 약 3GB RAM 필요.

⚠️ trace 포맷 버전 호환성 주의: gotraceui 최신 릴리스(v0.4.0)는 Go 1.21 이하의 구(舊) trace 포맷만 지원한다. 2장에서 다룬 것처럼 Go 1.22에서 trace 포맷이 새로 설계되었는데, gotraceui는 아직 이 신포맷을 읽지 못해 최신 Go로 생성한 trace를 열면 unsupported trace file version 에러가 발생한다. 또한 수 밀리초로 끝나는 짧은 trace는 trace too short로 거부된다. 따라서 gotraceui로 분석하려면 Go 1.21로 생성한, 수백 ms 이상 실행되는 프로그램의 trace가 필요하다. 최신 Go를 쓴다면 신포맷을 지원하는 공식 뷰어 go tool trace를 사용하거나, gotraceui의 신포맷 지원 릴리스를 기다려야 한다.

7.2 divan/gotrace (교육용 3D 시각화)

WebGL 기반 3D 애니메이션으로 goroutine과 채널 통신을 시각화한다.

• 파란 선 = goroutine 생명주기
• 빨간 화살표 = 채널을 통한 메시지 전달

fan-in, fan-out, worker pool 같은 동시성 패턴을 직관적으로 이해할 수 있어 교육 목적에 적합하다. 다만 채널 이벤트까지 기록하도록 패치된 옛 Go 런타임(Docker 이미지)을 요구하고, 짧은 프로그램만 시각화할 수 있다.

⚠️ 현재는 실행 불가: 2016년 이후 유지보수가 중단되어 지금 환경에서는 동작하지 않는다. 공식 Docker 이미지의 Go 버전(1.8)과 도구에 내장된 trace 파서(go 1.5 trace 포맷 전용)가 어긋나 not a trace file 에러가 발생하고, 옛 런타임으로 빌드한 바이너리도 최신 macOS에서는 실행되지 않는다. 따라서 아래 내용은 개념 이해용 참고로만 보고, 실제 시각화가 필요하다면 go tool trace나 gotraceui를 사용한다.

8. pprof와 trace 조합 활용

8.1 pprof vs trace

관점	pprof	trace
질문	"무엇이 리소스를 소비하는가?"	"무슨 일이 어떤 순서로 일어났는가?"
방식	샘플링 (통계적)	전수 기록 (정밀)
오버헤드	CPU 프로파일 ~5%	1-2% (Go 1.21+)
출력	플레임 그래프, top N	타임라인, goroutine 분석
강점	CPU/메모리 핫스팟 식별	인과관계, 타이밍, 동시성 분석

8.2 조합 워크플로우

flowchart TD
    A[성능 문제 발생] --> B[pprof CPU 프로파일 수집]
    B --> C[핫스팟 함수 식별]
    C --> D[trace 수집]
    D --> E[해당 구간의 goroutine 타이밍 분석]
    E --> F{동시성 문제?}
    F -- mutex 경합 --> G[lock 최적화]
    F -- 스케줄링 지연 --> H[GOMAXPROCS 조정]
    F -- GC pause --> I[메모리 할당 최적화]
    F -- I/O 블로킹 --> J[비동기 처리 도입]

8.3 trace가 pprof보다 유리한 경우

• goroutine 간 mutex 경합: pprof의 mutex 프로파일은 전체 경합 시간만 보여주지만, trace는 어떤 goroutine이 어떤 시점에 lock을 대기했는지 정확히 보여준다
• 스케줄링 latency: runnable이지만 P를 기다리는 시간은 pprof에서 보이지 않는다
• GC pause 영향: GC STW가 어떤 goroutine의 실행을 중단시켰는지 trace에서 확인 가능
• 채널 통신 패턴: 채널을 통한 데이터 흐름과 deadlock 가능성은 trace에서만 분석 가능

8.4 동시 수집 예제

pprof CPU 프로파일과 trace를 동시에 수집할 수 있다.

func TestPprof_Trace_동시수집(t *testing.T) {
    _ = os.MkdirAll("tmp", 0o755)
    traceFile, _ := os.Create("tmp/trace_combo.out")
    defer traceFile.Close()

    cpuFile, _ := os.Create("tmp/cpu_combo.prof")
    defer cpuFile.Close()

    // trace + CPU 프로파일 동시 시작
    rttrace.Start(traceFile)
    pprof.StartCPUProfile(cpuFile)

    // 워크로드 실행...

    // 수집 중지
    rttrace.Stop()
    pprof.StopCPUProfile()

    // 분석:
    // go tool trace tmp/trace_combo.out
    // go tool pprof tmp/cpu_combo.prof
}

8.5 HTTP pprof 엔드포인트

import _ "net/http/pprof"를 추가하면 기본 HTTP 서버에 프로파일링 엔드포인트가 자동 등록된다.

엔드포인트	설명
/debug/pprof/	인덱스 (사용 가능한 프로파일 목록)
/debug/pprof/profile	CPU 프로파일 (기본 30초)
/debug/pprof/trace	execution trace (기본 1초)
/debug/pprof/heap	메모리 할당 프로파일
/debug/pprof/goroutine	goroutine 스택 덤프
/debug/pprof/block	blocking 프로파일
/debug/pprof/mutex	mutex 경합 프로파일

9. 실전 예제: Concurrent Web Crawler 트레이싱

마지막으로 Worker Pool 패턴 기반의 간단한 웹 크롤러에 Task/Region/Log 계측을 적용하여, trace에서 어떤 정보를 얻을 수 있는지 살펴본다.

9.1 크롤러 구조

flowchart LR
    URLs[URL 채널] --> W1[Worker 1]
    URLs --> W2[Worker 2]
    URLs --> W3[Worker 3]

    W1 --> R[Results 채널]
    W2 --> R
    W3 --> R

    R --> Collect[결과 수집]

    subgraph "각 Worker의 처리 흐름"
        direction TB
        F[http-fetch Region] --> P[parse-html Region]
    end

9.2 계측 코드

func TestCrawler_Task_Region_계측(t *testing.T) {
    _ = os.MkdirAll("tmp", 0o755)
    f, _ := os.Create("tmp/trace_crawler.out")
    defer f.Close()

    rttrace.Start(f)
    defer rttrace.Stop()

    // httptest 서버로 외부 의존성 없는 테스트 구성
    pages := map[string]string{
        "/":        `<a href="/about">About</a><a href="/blog">Blog</a>`,
        "/about":   `<h1>About Us</h1><a href="/contact">Contact</a>`,
        "/blog":    `<h1>Blog</h1><a href="/blog/post1">Post 1</a>`,
        "/contact": `<h1>Contact</h1>`,
    }
    server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        time.Sleep(time.Duration(len(r.URL.Path)) * time.Millisecond)
        if body, ok := pages[r.URL.Path]; ok {
            fmt.Fprint(w, body)
        } else {
            http.NotFound(w, r)
        }
    }))
    defer server.Close()

    ctx := context.Background()
    ctx, mainTask := rttrace.NewTask(ctx, "web-crawler")
    defer mainTask.End()

    results := crawl(ctx, server.URL, server.Client(), 3)
    assert.NotEmpty(t, results, "크롤링 결과가 있어야 한다")
}

각 Worker는 URL을 받을 때마다 Task를 생성하고, HTTP 요청과 파싱을 각각 Region으로 감싼다.

for url := range urls {
    taskCtx, task := rttrace.NewTask(ctx, "crawl-page")
    rttrace.Log(taskCtx, "url", url)
    rttrace.Log(taskCtx, "worker", workerName)

    // Region으로 각 단계 계측
    rttrace.WithRegion(taskCtx, "http-fetch", func() {
        // HTTP 요청...
    })
    rttrace.WithRegion(taskCtx, "parse-html", func() {
        // HTML 파싱...
    })

    task.End()
}

9.3 예제 실행하기

위 코드는 tutorials-go 저장소에 테스트 형태로 들어 있다. 직접 실행해 trace를 수집하고 뷰어로 여는 과정은 다음과 같다.

# 1. 저장소 클론 후 trace 예제 디렉토리로 이동
git clone https://github.com/kenshin579/tutorials-go.git
cd tutorials-go/golang/concurrency/trace

# 2. 크롤러 테스트 실행 → tmp/trace_crawler.out 생성
go test -v -run TestCrawler_Task_Region_계측

# 3. 수집된 trace를 공식 뷰어로 열기 (브라우저 자동 실행)
go tool trace tmp/trace_crawler.out

테스트가 통과하면 tmp/trace_crawler.out 파일이 만들어지고, go tool trace가 로컬 웹 서버를 띄워 브라우저로 trace 뷰어를 연다. 브라우저가 자동으로 열리지 않으면 포트를 지정해 직접 접속할 수도 있다.

go tool trace -http=:6060 tmp/trace_crawler.out   # http://localhost:6060 접속

이 예제는 httptest 서버를 사용하므로 외부 네트워크 없이 동작한다. trace를 다 보고 나면 go tool trace는 Ctrl+C로 종료한다.

9.4 trace 분석 포인트

수집된 trace를 go tool trace로 열면, 인덱스 페이지에서 User-defined tasks와 User-defined regions 링크로 비즈니스 로직 수준의 분석에 바로 접근할 수 있다.

① Task별 latency — User-defined tasks 페이지에서는 Task 종류별로 latency 히스토그램을 보여준다.

crawl-page Task는 4번 실행되었고, 그중 1건은 1.5ms대, 3건은 6.310ms 구간에 몰려 있다. 이 예제의 테스트 서버는 URL 경로 길이에 비례해 응답을 지연시키도록 만들었기 때문에, 경로가 긴 페이지일수록 느리게 나타난 것이다. 전체 크롤링을 감싼 web-crawler Task는 1건으로 1015.8ms가 걸렸다.

② Region별 시간 비교 — User-defined regions 페이지에서 http-fetch와 parse-html 구간을 나란히 비교할 수 있다.

결과는 명확하다. http-fetch는 1.510ms인 반면, parse-html은 **251ns1µs**에 불과하다. 즉 크롤링 시간의 거의 전부가 네트워크 I/O(http-fetch)에서 소비되고 파싱 비용은 무시할 수준이라는 것을, trace만 보고도 단정할 수 있다. 최적화한다면 파싱이 아니라 동시 요청 수나 커넥션 재사용 같은 네트워크 쪽을 손대야 한다는 결론이 바로 나온다.

이 외에도 다음 뷰가 유용하다.

• Worker 활용률: Goroutine analysis에서 Worker goroutine이 실행 중인 시간 대비 채널 대기 시간의 비율을 확인
• 스케줄링 효율: Scheduler latency profile에서 Worker가 runnable이지만 P를 기다리는 시간을 확인

10. 정리

도구/기법	핵심	사용 시점
trace.Start/Stop	코드 삽입으로 정밀 구간 수집	개발/테스트 시 특정 구간 분석
go test -trace	코드 수정 없이 테스트 trace 수집	기존 테스트에서 빠르게 trace 확인
net/http/pprof	HTTP로 런타임 trace 수집	운영 중인 서버 분석
Task/Region/Log	비즈니스 로직 수준 계측	논리적 작업의 latency 분석
GODEBUG=schedtrace	스케줄러 매크로 상태 출력	빠른 스케줄러 상태 확인
Flight Recorder	이상 징후 시 자동 스냅샷	프로덕션 tail latency 디버깅
gotraceui	대용량 trace 분석 GUI	Chrome 없이 대용량 trace 분석
pprof + trace 조합	CPU 핫스팟 + 동시성 인과관계	복합적 성능 문제 분석

동시성 코드의 성능 문제와 버그는 로그와 추측만으로는 해결하기 어렵다. go tool trace를 활용해 데이터 기반으로 분석하는 습관을 들이자. Go 1.21 이후 trace 오버헤드가 1-2%로 크게 줄어든 만큼, 개발·테스트 단계에서 병목이 의심될 때 부담 없이 trace를 수집해 들여다보면 된다.

예제 코드는 GitHub에서 확인할 수 있다.

11. 참고

• More powerful Go execution traces (Go Blog, 2024)
• Flight Recorder in Go 1.25 (Go Blog)
• runtime/trace 공식 문서
• Execution tracer overhaul design proposal (#60773)
• Scheduler Tracing In Go (Ardan Labs)
• gotraceui (GitHub)
• divan/gotrace (GitHub)
• Visualizing Concurrency in Go (divan blog)