pprof 프로파일링

이 챕터에서 다루는 것

"느리다"와 "메모리가 샌다"를 추측이 아니라 데이터로 다루는 도구들이다. 프로파일의 종류와 읽는 법, 서버에 안전하게 노출하는 법, 그리고 사후에 트레이스를 되감는 FlightRecorder까지.

이 챕터의 숫자는 대부분 실행마다 다르다. 어느 값이 변하고 어느 것이 안 변하는지를 그때그때 밝힌다.

문제 — 추측은 거의 항상 틀린다

성능 문제를 만나면 코드를 읽고 "여기가 느릴 것 같다"고 짐작하게 된다. 그 짐작이 맞는 비율은 생각보다 낮다. 실제로는 이런 것들이 범인이다.

• 로그 한 줄에 들어 있는 fmt.Sprintf가 초당 수만 번 불린다
• 슬라이스를 append로 키우는 루프가 배열을 열두 번 재할당한다
• ORM이 만든 쿼리가 요청당 40개다 (11-4)
• 정작 CPU는 놀고 있고 전부 DB를 기다리는 시간이다

Go에는 이것을 재는 도구가 표준으로 들어 있다. 먼저 재고, 그다음에 고친다.

프로파일의 종류

runtime/pprof가 기본으로 제공하는 프로파일은 여섯 개다.

== 1. 이 프로그램이 가진 프로파일 ==
  allocs         프로그램 시작 이후 모든 할당. 해제된 것 포함
  block          동기화 대기 시간. runtime.SetBlockProfileRate 필요
  goroutine      지금 살아 있는 고루틴의 스택. 누수 진단의 1번 도구
  heap           살아 있는 객체의 할당 위치
  mutex          락 경합. runtime.SetMutexProfileFraction 필요
  threadcreate   OS 스레드 생성 지점. 쓸 일이 거의 없다

여기에 목록에 없는 CPU 프로파일이 따로 있다. CPU 프로파일만 "기간"을 갖기 때문에 pprof.StartCPUProfile/StopCPUProfile로 따로 다룬다. 나머지는 전부 "지금 이 순간의 스냅숏"이다.

프로파일	답하는 질문	비용
CPU	시간을 어디서 태우는가	켜 놓는 동안 약간. 100Hz 표본
heap	지금 살아 있는 메모리를 누가 잡고 있는가	거의 없음(표본 추출)
allocs	할당을 누가 많이 하는가 (GC 부담)	거의 없음
goroutine	고루틴이 몇 개고 어디서 막혀 있는가	스냅숏 시 STW 짧게
block	채널·뮤텍스를 기다리는 시간이 어디인가	기본 꺼짐. 켜면 비쌈
mutex	락 경합이 어디인가	기본 꺼짐. 켜면 비쌈

:::warning block/mutex 프로파일은 기본이 꺼져 있다

runtime.SetBlockProfileRate(1)      // 모든 블록 이벤트 기록 — 매우 비싸다
runtime.SetMutexProfileFraction(1)  // 모든 경합 기록

1은 "전부"라서 운영에서 쓰면 안 된다. 문제를 재현하는 동안만 켜거나, SetBlockProfileRate(10000)(10마이크로초 이상만) 정도로 표본을 줄인다. :::

서버에 노출하기 — 별도 포트에

net/http/pprof를 import하면 HTTP로 프로파일을 받을 수 있다. 문제는 어떻게 붙이느냐다.

import _ "net/http/pprof" // 이렇게 하면 안 된다

빈 import의 부작용으로 http.DefaultServeMux에 /debug/pprof/*가 등록된다. 서비스가 DefaultServeMux를 쓰고 있다면 공개 포트에 프로파일 엔드포인트가 열린다.

examples/12-production/04-pprof/pprofserver/pprofserver.go

// adminMux는 pprof 엔드포인트를 직접 등록한다.
//
// net/http/pprof를 빈 import(_)로 넣으면 http.DefaultServeMux에 자동
// 등록되는데, 그러면 서비스 라우터와 같은 포트에 노출된다. 그것이
// 실제 사고로 이어진 적이 여러 번 있다 — /debug/pprof/profile을
// 아무나 부를 수 있으면 30초짜리 CPU 프로파일을 반복 요청해서
// 서비스를 느리게 만들 수 있고, 힙 프로파일에는 메모리에 있던
// 문자열의 흔적이 남는다.
//
// 그래서 여기서는 별도 리스너에 명시적으로 붙인다. 이 포트는
// 방화벽이나 쿠버네티스 NetworkPolicy로 내부에만 열어 둔다.
func adminMux() http.Handler {
	mux := http.NewServeMux()
	mux.HandleFunc("/debug/pprof/", pprof.Index)
	mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
	mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
	mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
	mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
	return mux
}

pprof.Index가 /debug/pprof/heap 같은 이름 기반 경로를 알아서 처리한다. 따로 등록해야 하는 것은 cmdline, profile, symbol, trace 넷뿐이다.

서비스 포트와 관리 포트를 나누는 것은 pprof만의 이야기가 아니다. 12-2의 로그 레벨 변경 엔드포인트, 12-8의 헬스체크도 같은 포트에 모인다.

이 서버는 무한히 도는 프로그램이라 빌드 태그를 걸어 두었다.

go run -tags pprofserver ./04-pprof/pprofserver

curl 'http://127.0.0.1:8080/work?rounds=200000'
go tool pprof -http=:0 'http://127.0.0.1:6060/debug/pprof/profile?seconds=10'
go tool pprof -http=:0 'http://127.0.0.1:6060/debug/pprof/heap'
curl 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1' | head -30

-http=:0은 빈 포트를 골라 브라우저를 띄운다. -http=:8081처럼 고정해도 된다.

웹 UI는 이제 화염 그래프가 기본이다

Go 1.26에서 go tool pprof의 웹 UI 기본 화면이 바뀌었다. 예전에는 호출 그래프 (네모와 화살표)가 먼저 떴는데, 이제 화염 그래프가 먼저 뜬다. 표준 라이브러리에 들어 있는 pprof 소스의 라우팅 표에 그대로 적혀 있다.

$GOROOT/src/cmd/vendor/github.com/google/pprof/internal/driver/webui.go:128
			"/":             redirectWithQuery("flamegraph", http.StatusMovedPermanently),
			"/graph":        http.HandlerFunc(ui.dot),
			"/top":          http.HandlerFunc(ui.top),
			"/disasm":       http.HandlerFunc(ui.disasm),
			"/source":       http.HandlerFunc(ui.source),
			"/peek":         http.HandlerFunc(ui.peek),
			"/flamegraph":   http.HandlerFunc(ui.stackView),

예전 그래프 화면은 View → Graph 메뉴나 /ui/graph 경로에 있다. 오래된 블로그 글의 스크린샷과 지금 화면이 다른 이유가 이것이다.

화염 그래프 읽는 법은 간단하다. 가로 폭이 비용이고, 세로가 호출 깊이다. 넓은 막대를 찾아 아래로 내려가면 된다. 왼쪽에서 오른쪽 순서에는 의미가 없다(알파벳 순이다).

명령줄로 읽기

브라우저 없이도 충분히 쓸 만하다. 예제의 leaky.Hash를 3000만 번 돌려 CPU 프로파일을 찍고 -top -cum으로 본 실제 결과다.

File: gen
Type: cpu
Time: 2026-08-12 19:58:35 KST
Duration: 1.71s, Total samples = 1.27s (74.33%)
Showing nodes accounting for 1.06s, 83.46% of 1.27s total
Showing top 12 nodes out of 51
      flat  flat%   sum%        cum   cum%
         0     0%     0%      1.11s 87.40%  runtime.systemstack
         0     0%     0%      1.04s 81.89%  runtime.gcStart.func4
     1.04s 81.89% 81.89%      1.04s 81.89%  runtime.kevent
         0     0% 81.89%      1.04s 81.89%  runtime.netpoll
         0     0% 81.89%      1.04s 81.89%  runtime.startTheWorldWithSema
         0     0% 81.89%      0.17s 13.39%  example.com/production/04-pprof/leaky.Hash
         0     0% 81.89%      0.17s 13.39%  main.main
         0     0% 81.89%      0.17s 13.39%  runtime.main
     0.01s  0.79% 82.68%      0.09s  7.09%  runtime.mallocgc
         0     0% 82.68%      0.09s  7.09%  runtime.newobject
     0.01s  0.79% 83.46%      0.08s  6.30%  crypto/internal/fips140/sha256.(*Digest).Sum
         0     0% 83.46%      0.08s  6.30%  crypto/sha256.Sum256

모든 숫자는 실행마다 다르다. 표본 추출이고, 머신 상태에 따라 달라진다. 여기서 읽어야 할 것은 값이 아니라 구조다.

• flat — 그 함수 자체에서 쓴 시간. cum — 그 함수와 그것이 부른 것들의 합. 최적화 대상을 찾을 때는 cum으로 내려가다가 flat이 큰 지점에서 멈춘다.
• -top은 기본이 flat 정렬, -cum을 붙이면 cum 정렬이다.
• Duration 1.71s, Total samples = 1.27s (74.33%) — 벽시계로 1.71초 도는 동안 CPU 표본은 1.27초어치였다는 뜻이다. 100%가 안 되는 것은 정상이다.

:::warning macOS에서 runtime.kevent가 1등으로 뜬다 위 출력에서 82%가 runtime.kevent인데, 이것은 진짜 병목이 아니다. 호출 경로가 gcStart → startTheWorldWithSema → netpoll → kevent인 데서 보이듯 런타임이 네트워크 폴러를 깨우는 자리이고, darwin에서 CPU 프로파일이 이 구간을 과다 계상한다. 같은 코드를 linux에서 프로파일하면 나타나지 않는다.

프로파일에 런타임 내부 함수가 1등으로 뜨면 먼저 의심한다. 애플리케이션 코드로 좁혀 보는 것이 -focus다. :::

go tool pprof -top -cum -focus='leaky.Hash' -nodecount=10 cpu.pprof

Active filters:
   focus=leaky.Hash
Showing nodes accounting for 0.05s, 3.94% of 1.27s total
Showing top 10 nodes out of 35
      flat  flat%   sum%        cum   cum%
         0     0%     0%      0.17s 13.39%  example.com/production/04-pprof/leaky.Hash
         0     0%     0%      0.17s 13.39%  main.main
         0     0%     0%      0.17s 13.39%  runtime.main
     0.01s  0.79%  0.79%      0.09s  7.09%  runtime.mallocgc
         0     0%  0.79%      0.09s  7.09%  runtime.newobject
     0.01s  0.79%  1.57%      0.08s  6.30%  crypto/internal/fips140/sha256.(*Digest).Sum
         0     0%  1.57%      0.08s  6.30%  crypto/sha256.Sum256
     0.01s  0.79%  2.36%      0.08s  6.30%  runtime.mallocgcSmallNoscan
     0.01s  0.79%  3.15%      0.07s  5.51%  crypto/internal/fips140/sha256.(*Digest).checkSum
     0.01s  0.79%  3.94%      0.06s  4.72%  crypto/internal/fips140/sha256.(*Digest).Write

이제 뭔가 보인다. Hash가 쓴 0.17초 중 **0.09초(전체의 절반 이상)가 runtime.mallocgc**다. 해시를 계산하는 시간보다 할당하는 시간이 길다는 뜻이고, 이것이 12-5가 다룰 주제다.

자주 쓰는 명령들이다.

명령	하는 일
top, top -cum	상위 함수
list 함수이름	소스 줄마다 비용
peek 함수이름	그 함수를 부른 쪽과 부른 쪽
web	그래프를 SVG로 (Graphviz 필요)
-focus=, -ignore=, -hide=	정규식 필터
-diff_base=old.pprof	두 프로파일의 차이

-diff_base는 "고쳤는데 정말 나아졌나"에 답할 때 쓴다. 12-5에서 벤치마크로 같은 질문에 답하는 다른 방법을 본다.

고루틴 누수 — 개수부터

고루틴 누수는 Go에서 가장 흔한 메모리 누수 형태다. 고루틴 하나가 최소 몇 KB의 스택을 잡고 있고, 그것이 참조하는 것들도 함께 살아남는다.

examples/12-production/04-pprof/leaky/leaky.go

// Leak는 영원히 깨어나지 않는 고루틴을 n개 만든다.
//
// 채널이 지역 변수라 함수가 돌아오는 순간 아무도 그것에 쓸 수 없다.
// 그래도 고루틴들은 수신을 기다리며 남는다. 파트 7-1에서 본 그 누수이고,
// 실제 코드에서는 "응답을 기다리는데 요청 쪽이 이미 포기한" 모양으로 나온다.

진단의 첫걸음은 프로파일러가 아니라 숫자 하나다.

== 2. 고루틴 누수를 숫자로 ==
  Leak(50) 전: 1개
  Leak(50) 후: 51개 (+50)
  release() 후 원래대로 돌아왔는가: true
  NoLeak(50) 후: +50 (여기까지는 똑같이 생겼다)
  cancel() 후 원래대로 돌아왔는가: true
  차이는 select 하나다 — Leak에는 빠져나갈 case가 없다

runtime.NumGoroutine()을 지표로 내보내고 그래프를 그려 두면, 누수는 단조 증가하는 직선으로 나타난다. 부하가 없는 새벽에도 안 내려가면 누수다. 이 그래프 하나가 프로파일러보다 먼저 문제를 알려 준다.

테스트에서도 같은 방법이 통한다.

examples/12-production/04-pprof/leaky/leaky_test.go

// TestLeakIsDetectableByCounting은 가장 값싼 누수 테스트다.
//
// 테스트 시작과 끝의 고루틴 수를 비교한다. 프로파일러를 붙일 필요도
// 없고, 누수를 만드는 코드 변경이 들어오면 CI에서 바로 걸린다.
func TestLeakIsDetectableByCounting(t *testing.T) {
	before := leaky.Goroutines()

	release := leaky.Leak(20)
	if got := leaky.Goroutines() - before; got != 20 {
		t.Fatalf("고루틴 증가 %d, 20을 기대", got)
	}

	release()
	if !leaky.WaitGoroutines(before, 100_000) {
		t.Fatalf("release 후에도 %d개가 남아 있다", leaky.Goroutines()-before)
	}
}

time.Sleep으로 "충분히" 기다리지 않는 것에 주목한다. 조건을 확인하며 양보하는 편이 느린 CI 머신에서도 깨지지 않는다. 파트 8-7의 testing/synctest가 답인 경우도 많지만, runtime.NumGoroutine은 버블 밖의 고루틴까지 세므로 여기서는 직접 기다린다.

고루틴 누수 — 범인의 이름

숫자는 "늘었다"만 알려 준다. 어디서 늘었는지는 고루틴 프로파일에 있다.

examples/12-production/04-pprof/main.go

// whereBlocked는 고루틴 프로파일을 읽어 "무엇을 기다리는 고루틴이 몇 개인지"를 센다.
//
// debug=1로 쓰면 사람이 읽는 형식이 나온다. 첫 줄이
// "N @ 주소들"이고 그 아래에 스택이 붙는다. 주소는 실행마다 다르므로
// 함수 이름만 골라 센다.
func whereBlocked() {
	release := leaky.Leak(50)
	defer release()

	var buf bytes.Buffer
	if err := pprof.Lookup("goroutine").WriteTo(&buf, 1); err != nil {
		log.Fatal(err)
	}

== 3. 누수한 고루틴이 어디서 막혔는지 ==
  leaky.Leak.func1 프레임이 1번 나온다
  (스택 하나에 고루틴 50개가 묶여 나오므로 줄 수와 고루틴 수는 다르다)
  goroutine profile: total 51

같은 스택을 가진 고루틴은 하나로 묶여 나온다. 50 @ 0x... 다음에 스택이 한 번 찍히는 식이다. 그래서 "몇 줄이 있나"가 아니라 앞의 숫자를 봐야 한다. 테스트로 그 형식을 못 박아 두면 잊지 않는다.

examples/12-production/04-pprof/leaky/leaky_test.go

	// 같은 스택의 고루틴은 하나로 묶여 "20 @ ..." 형태로 나온다.
	if !strings.Contains(out, "\n20 @ ") {
		t.Fatalf("20개가 한 스택으로 묶여 나와야 한다:\n%s", out)
	}

운영에서는 이 명령이 첫 수다.

curl 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1' | head -30

맨 앞의 큰 숫자 하나가 대개 범인이다.

실험적 goroutineleak 프로파일

Go 1.26에 실험으로 들어온 기능이다. GC의 도달 가능성 분석을 이용해 영원히 깨어날 수 없는 고루틴을 찾아낸다. 고루틴 프로파일이 "지금 막혀 있다"까지만 말하는 데 비해, 이쪽은 "앞으로도 깨어날 수 없다"를 판정한다.

examples/12-production/04-pprof/leakprofile/leakprofile.go

	// 누수 판정은 GC의 도달 가능성 분석으로 한다. GC가 돌아야
	// 결과가 나오므로 명시적으로 부른다.
	runtime.GC()
	runtime.GC()

	p := pprof.Lookup("goroutineleak")
	if p == nil {
		log.Fatal("goroutineleak 프로파일이 없다 — GOEXPERIMENT를 켰는지 확인한다")
	}

	// Count()는 0이다. 이 프로파일은 WriteTo 시점에 분석을 수행하므로
	// 미리 세어 둔 값이 없다. 다른 프로파일과 다른 점이다.
	fmt.Println("Count() =", p.Count())

GOEXPERIMENT=goroutineleakprofile go run ./04-pprof/leakprofile

이 머신에서 실제로 나온 출력이다.

Count() = 0
goroutineleak profile: total 3
3 @ 0x1021d103c 0x10216baf0 0x10216b674 0x102225928 0x1021d78f4
#	0x102225927	example.com/production/04-pprof/leaky.Leak.func1+0x37	/Users/sgn04088/golang-lecture/examples/12-production/04-pprof/leaky/leaky.go:31

16진수 주소와 파일 경로는 당연히 환경마다 다르다. 변하지 않는 것은 **total 3**과 범인의 함수 이름·줄 번호다. 누수시킨 고루틴이 정확히 셋이었고, 그것을 도구가 스스로 찾아냈다.

Count()가 0인 것도 알아 둘 만하다. 다른 프로파일은 미리 세어 둔 값을 갖고 있지만, 이 프로파일은 WriteTo 시점에 분석을 수행하므로 셀 것이 미리 없다.

빌드 태그도 눈여겨볼 만하다.

examples/12-production/04-pprof/leakprofile/leakprofile.go

//go:build goexperiment.goroutineleakprofile

GOEXPERIMENT를 켜면 툴체인이 goexperiment.<이름> 빌드 태그를 자동으로 넣는다. 그래서 -tags를 따로 줄 필요가 없고, 실험을 켜지 않은 빌드에서는 이 파일이 아예 컴파일되지 않는다.

:::warning 실험 기능이다 GOEXPERIMENT로 켜는 기능은 다음 릴리스에서 이름이 바뀌거나 사라질 수 있다. CI나 운영 배포에 넣지 말고, 문제를 조사할 때 로컬에서 켜는 도구로 쓴다. :::

runtime/metrics — 지표로 내보낼 것들

프로파일이 "지금 자세히 들여다보기"라면, runtime/metrics는 "계속 지켜보기"다. Prometheus 같은 곳으로 내보내 그래프를 그리는 값들이다.

examples/12-production/04-pprof/main.go

	// Go 1.26에서 늘어난 스케줄러 지표들. 이름이 곧 계약이므로
	// metrics.All()로 존재를 확인하고 쓰는 편이 안전하다.
	names := []string{
		"/sched/gomaxprocs:threads",
		"/sched/goroutines:goroutines",
		"/sched/goroutines/running:goroutines",
		"/sched/goroutines/runnable:goroutines",
		"/sched/goroutines/waiting:goroutines",
		"/sched/goroutines-created:goroutines",
		"/sched/threads/total:threads",
	}

== 4. runtime/metrics 스케줄러 지표 ==
  /sched/gomaxprocs:threads              uint64
  /sched/goroutines:goroutines           uint64
  /sched/goroutines/running:goroutines   uint64
  /sched/goroutines/runnable:goroutines  uint64
  /sched/goroutines/waiting:goroutines   uint64
  /sched/goroutines-created:goroutines   uint64
  /sched/threads/total:threads           uint64
  GOMAXPROCS=10 NumCPU=10 — 컨테이너에서는 이 둘이 달라진다

값은 찍지 않았다. 실행마다 다르기 때문이고, 여기서 확인하고 싶은 것은 이 이름들이 이 런타임에 존재한다는 사실뿐이다.

runnable이 특히 쓸모 있다. "실행할 준비가 됐지만 CPU를 못 받은 고루틴 수"이므로, 이 값이 꾸준히 높으면 GOMAXPROCS가 부족하거나 CPU가 모자란다는 뜻이다. 12-7에서 컨테이너의 CPU 제한과 함께 볼 값이다.

:::danger 지표 이름을 오타 내면 조용히 0이 된다 metrics.Read는 모르는 이름에 대해 에러를 내지 않고 Kind를 KindBad로 둔다. 그 값을 그대로 Uint64()로 읽으면 0이 나오고, "지표가 0이다"와 구별되지 않는다. 반드시 Kind를 확인한다.

examples/12-production/04-pprof/main.go

		if s.Value.Kind() == metrics.KindBad {
			// 이름이 틀렸거나 이 버전에 없는 지표다. 조용히 0을 쓰면
			// "지표가 0이다"와 구별되지 않으므로 반드시 구분해야 한다.
			fmt.Printf("  %-38s (이 런타임에 없음)\n", s.Name)
			continue
		}

:::

11-2에서 db.Stats()의 WaitCount와 WaitDuration을 지표로 내보내야 한다고 했다. 같은 자리다 — 런타임 지표와 커넥션 풀 지표를 같은 수집기에 붙여 두면, "느리다"는 신고를 받았을 때 CPU 부족인지 커넥션 부족인지를 그래프 두 개로 가른다.

FlightRecorder — 이미 지나간 일을 보기

프로파일링의 근본적인 난점은 문제가 일어난 뒤에 도구를 켜게 된다는 것이다. "가끔 응답이 10초 걸린다"는 현상은 그때 트레이스를 켜고 있어야 잡히는데, 항상 켜 두기엔 트레이스가 비싸다.

Go 1.25의 runtime/trace.FlightRecorder가 이 문제를 푼다. 최근 몇 초를 메모리 링 버퍼에 계속 담고 있다가, 필요할 때 그것을 덤프한다. 블랙박스와 같은 발상이다.

examples/12-production/04-pprof/main.go

func flightRecorder() {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
	if err := fr.Start(); err != nil {
		log.Fatal(err)
	}
	defer fr.Stop()

	fmt.Println("  Enabled():", fr.Enabled())
	leaky.Hash("seed", 50_000)

	// 이상 상황을 감지한 순간 WriteTo를 부른다. 링 버퍼에 남아 있던
	// 최근 몇 초가 그대로 트레이스 파일이 된다.
	var buf bytes.Buffer
	n, err := fr.WriteTo(&buf)
	if err != nil {
		log.Fatal(err)
	}
	fmt.Println("  WriteTo가 뭔가 썼는가:", n > 0)
	fmt.Println("  이 바이트를 파일로 저장하면 go tool trace로 열린다")
}

== 6. FlightRecorder — 사후에 되감기 ==
  Enabled(): true
  WriteTo가 뭔가 썼는가: true
  이 바이트를 파일로 저장하면 go tool trace로 열린다

n은 실행마다 다르므로 값 대신 n > 0만 찍었다.

실전에서는 이렇게 쓴다. 미들웨어에서 응답 시간을 재다가 임계값을 넘으면 WriteTo로 파일을 하나 떨군다. 그 파일에는 느렸던 그 요청이 처리되던 몇 초가 들어 있다. go tool trace 파일로 열면 고루틴별 타임라인, GC 구간, 스케줄러 지연이 다 보인다.

동시에 하나만 활성화할 수 있다는 제약이 있다(문서에 명시돼 있다). 그리고 FlightRecorderConfig로 버퍼 크기와 보관 기간을 조절한다.

흔한 실수

_ "net/http/pprof"를 공개 포트에 노출한다. 이 챕터의 첫 경고다.

프로파일을 안 켜고 최적화한다. 12-5의 주제이기도 하다.

heap과 allocs를 혼동한다. heap은 "지금 살아 있는 것"이라 메모리 누수 진단용이고, allocs는 "지금까지 할당한 전부"라 GC 부담 진단용이다. -inuse_space(기본)와 -alloc_space 플래그로 같은 프로파일을 두 관점에서 볼 수도 있다.

표본 수가 적은 프로파일을 믿는다. Total samples가 몇십 밀리초면 통계적으로 의미가 없다. CPU 프로파일은 최소 10초, 부하가 걸린 상태에서 받는다.

block 프로파일을 운영에 켜 둔다. SetBlockProfileRate(1)은 모든 채널 연산을 기록한다. 재현할 때만 켠다.

GOTRACEBACK이나 프로파일로 개인정보를 흘린다. 힙 프로파일 자체에는 값이 없지만, goroutine?debug=2는 스택 인자를 포함하고 크래시 덤프는 더 많은 것을 담는다. 관리 포트를 내부에 두는 이유가 이것이기도 하다.

로컬에서 프로파일하고 운영을 판단한다. 위의 runtime.kevent 사례가 그 예다. 아키텍처와 OS가 다르면 프로파일도 다르다.

정리

• 재고 나서 고친다. 짐작은 대체로 틀린다.
• 프로파일은 여섯 개 + CPU. block/mutex는 기본 꺼짐이고 켜면 비싸다.
• net/http/pprof는 별도 포트에 명시적으로 등록한다. 빈 import는 DefaultServeMux에 붙는다.
• 웹 UI 기본 화면은 이제 화염 그래프다. 옛 그래프는 View → Graph.
• flat은 자기 시간, cum은 자식 포함. -focus로 애플리케이션 코드만 본다.
• 고루틴 누수는 개수 → 스택 순으로 좁힌다. NumGoroutine() 그래프가 첫 경보다.
• goroutineleak 프로파일은 "깨어날 수 없음"을 판정한다. 실험 기능이다.
• runtime/metrics는 계속 지켜볼 값들. KindBad를 반드시 확인한다.
• FlightRecorder는 이미 지나간 몇 초를 되감는다.

연습문제

1. pprofserver를 띄우고 /leak?n=100을 다섯 번 호출한 뒤, /debug/pprof/goroutine?debug=1의 첫 줄이 어떻게 변하는지 보자. 그다음 go tool pprof -http=:0 'http://127.0.0.1:6060/debug/pprof/goroutine'으로 열어 화염 그래프에서 같은 것을 찾아보자. 어느 쪽이 빨랐는가?

2. leaky.Hash의 CPU 프로파일에서 runtime.mallocgc가 절반을 차지했다. list leaky.Hash로 어느 줄이 할당하는지 찾아보자. sha256.Sum256이 배열을 돌려주는데 왜 힙 할당이 생기는가? (힌트: sum = h[:]가 무엇을 하는지, 그리고 그 슬라이스가 다음 반복까지 살아남는다는 것)

3. 미들웨어 하나를 만들어, 응답 시간이 100ms를 넘으면 FlightRecorder.WriteTo로 트레이스를 파일에 떨구게 해 보자. 파일 이름이 겹치지 않게 하고, 디스크가 가득 차지 않도록 하는 장치를 넣어야 한다. 어떤 장치가 필요한가? (힌트: 마지막 덤프 시각, 파일 개수 상한)