Go上級 #6 プロファイリング — pprof と benchmark

プログラミング言語 Go Go プロファイリング パフォーマンス
読了 5分

#5 unsafe と cgoの次、今回は正反対の毛色のツール。計測。

“Don’t guess; measure.”

性能問題はほぼ常に — 私たちが疑った箇所ではなく別の箇所で発生します。Goは標準ツールが強力なので — 当てずっぽうではなく素早く計測へ向かえます。

benchmark — 標準ツール #

シンプルな benchmark 
// adder_test.go
package adder

import "testing"

func BenchmarkAdd(b *testing.B) {
	for i := 0; i < b.N; i++ {
		Add(1, 2)
	}
}
実行 
go test -bench=. -benchmem
結果 
BenchmarkAdd-8    1000000000    0.30 ns/op    0 B/op    0 allocs/op
  • b.N — 計測時間が安定するまで自動調整
  • -benchmem — 割り当て情報を追加
  • ns/op — 1回の実行にかかる時間
  • B/op / allocs/op — メモリ割り当て量と回数

benchmark 作成の基本 #

reset パターン 
func BenchmarkParse(b *testing.B) {
	data := loadBigInput()    // 重い準備

	b.ResetTimer()             // ここから計測
	for i := 0; i < b.N; i++ {
		Parse(data)
	}
}

準備コストは — ResetTimerで分離。b.StopTimer / b.StartTimerでループの中でも一時停止可能。

コンパイラ最適化の回避 #

よく出会う罠 
func BenchmarkSum(b *testing.B) {
	for i := 0; i < b.N; i++ {
		sum(1, 2)    // ✗ 結果を使わないとコンパイラが丸ごと除去しうる
	}
}

解決 — 結果をパッケージレベルの変数に代入(コンパイラに除去させない)。

結果保存 
var benchResult int

func BenchmarkSum(b *testing.B) {
	var r int
	for i := 0; i < b.N; i++ {
		r = sum(1, 2)
	}
	benchResult = r
}

benchstat — 2つの結果を比較 #

改善前後の比較 
go test -bench=. -count=10 > before.txt
# コード修正
go test -bench=. -count=10 > after.txt

go install golang.org/x/perf/cmd/benchstat@latest
benchstat before.txt after.txt
              │   before   │            after            │
              │   sec/op   │   sec/op    vs base         │
Parse-8       │ 1.23µ ± 2% │ 0.85µ ± 1%  -30.89% (p=0.000 n=10)

p値で有意な差かどうかを判断。1回だけ回すとノイズに騙されます — -count=10を推奨。

CPU プロファイル #

benchmark から CPU プロファイル 
go test -bench=. -cpuprofile=cpu.out
go tool pprof cpu.out
pprof インタラクティブ 
(pprof) top
Showing nodes accounting for 1.23s, 87.86% of 1.4s total
      flat  flat%   sum%        cum   cum%
     0.43s 30.71% 30.71%      0.65s 46.43%  parse
     0.31s 22.14% 52.86%      0.31s 22.14%  hash
     ...

(pprof) list parse
(pprof) web      ← ブラウザでコールグラフ

topで最も時間を使う関数を見て、list <fn>で行ごとの時間を確認。

メモリプロファイル #

go test -bench=. -memprofile=mem.out
go tool pprof -alloc_space mem.out

2つの視点:

  • -alloc_space — 累計割り当て量(これがGC負荷を最もよく見せる)
  • -inuse_space — 現在生きているメモリ

ホットパスで割り当てが多いと — GCが頻繁に走ってthroughputが下がります。通常はescape analysisと共に分析。

Escape analysis #

go build -gcflags='-m' main.go
結果例 
./main.go:5:9: &User{...} escapes to heap

スタックに残ってもよかったオブジェクトが — どんな理由でヒープ割り当てに回されたかを教えてくれます。メモリ割り当てを減らす作業の出発点。

プロダクションプロファイル — net/http/pprof #

pprof endpoint 
import (
	"net/http"
	_ "net/http/pprof"    // /debug/pprof/* endpoint 自動登録
)

func main() {
	go http.ListenAndServe(":6060", nil)
	// 本サーバーは別途...
}
リアルタイムプロファイル 
# 30 秒間 CPU プロファイル
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30

# 現在のメモリ
go tool pprof http://localhost:6060/debug/pprof/heap

# 現在のゴルーチン
go tool pprof http://localhost:6060/debug/pprof/goroutine

プロダクションで — サービスを止めずにプロファイル可能。ただし6060ポートが外部に露出しないよう注意(internal only)。

ゴルーチンリーク探し #

curl http://localhost:6060/debug/pprof/goroutine?debug=1

現在生きているすべてのゴルーチンのスタック。数が増え続けるならリーク。中級 #3で見たリークパターンが疑われるときの最初のツール。

Trace — 時間軸分析 #

CPU/メモリプロファイルが「どこ」なら、traceは「いつ」。

trace 収集 
go test -bench=. -trace=trace.out
go tool trace trace.out

ブラウザが開き — ゴルーチンスケジューリング、GCの時点、システムコールのようなものが時間軸で見えます。GCが頻繁に走るのか、ゴルーチンがstarvationしているのかのような時間軸の問題に似合います。

Race detector #

#2でちらっと見ました。

go test -race ./...
go run -race main.go

テストとローカル実行で常にオン。CIでもrace buildを別に回すのが良いです。オーバーヘッドが5〜10倍程度大きいので — プロダクションではオンにしません。

計測ワークフロー #

典型的な流れ:

  1. ユーザー/メトリクスが遅いと教えてくれる
  2. CPUプロファイル → どの関数に時間が使われているか
  3. (メモリが疑わしければ)メモリプロファイル → どこで多く割り当てているか
  4. 疑わしい箇所にベンチマークを書く — 再現可能な計測環境
  5. 修正 + benchstatで比較 — 本当に速くなったか
  6. 本番環境に再デプロイ — メトリクスで再確認

中核は — 各段階で計測による検証。推測だけで最適化すると — 実際にはより遅くなる場合がよくあります。

よく出会う場面 #

文字列連結 #

for ループでの + 
var s string
for _, p := range parts {
	s += p    // ✗ 毎回新しい string を割り当て
}

解決 — strings.Builder。

var b strings.Builder
for _, p := range parts {
	b.WriteString(p)
}
s := b.String()

slice の capacity 未指定 #

capacity を事前確保 
result := make([]int, 0, len(items))    // ✓ capacity を事前に
for _, x := range items {
	result = append(result, transform(x))
}

make([]int, 0)で始めると — 何度も再割り当て。事前にcapacityを与えれば1回の割り当てで終了。

map の capacity #

m := make(map[string]int, expectedSize)

mapも — 予想サイズを与えればreallocationを減らせます。

インターフェースのボックス化 #

インターフェース変換のコスト 
var any interface{} = 42    // int → interface{} ボックス化 (heap 割り当てが起こりうる)

ホットループでinterface{}(またはany)に変換することが頻繁なら割り当てが累積。可能なら — 具体型で。

まとめ #

今回の記事で整理した内容:

  • benchmark — b.N、-benchmem、ResetTimer、結果保存で最適化回避
  • benchstat — 2つの計測の統計的比較
  • CPUプロファイル — top、list、web
  • メモリプロファイル — -alloc_spaceが通常はより有用
  • escape analysis — -gcflags='-m'でヒープ割り当ての原因
  • net/http/pprof — プロダクションのリアルタイム計測
  • trace — 時間軸、GC、スケジューリング
  • race detector — 常にテストでオン
  • ワークフロー: メトリクス → プロファイル → ベンチ → 修正 → benchstat → 再確認

次の記事(#7 コード生成)では — Goがよく推奨するもう1つの道。reflectのコストを避けながら自動化する方法、go generateとstringerのような標準ツールを整理します。

X