Go を pprof でプロファイリング: CPU、メモリ、goroutine のボトルネック検出

1. 概要

Go のサービスが遅くなったり、RAM を消費したりするとき、推測では時間がかかり、誤りやすいです。Go には標準ライブラリに組み込みの pprof ツールがあります。このツールは、どの関数が CPU を消費し、どこでメモリが割り当てられ、どの goroutine がスタックしているかを正確に教えてくれます。

この記事を読み終わると、HTTP サービスで pprof を有効にする方法、ベンチマークと CLI プログラムからプロファイルを収集する方法、go tool pprof で結果を読む方法、そして 2 つのプロファイルを比較して最適化の効果を検証する方法がわかります。

2. pprof とは何か、どのような種類のプロファイルがあるか

pprof は 2 つの部分から構成されています：

収集側：標準ライブラリの runtime/pprof パッケージと net/http/pprof パッケージ。これらは protobuf 形式でプロファイルを記録します。
分析側：go tool pprof コマンド。このコマンドは、プロファイルファイルまたは URL を読み込み、テーブル、ソースコード、または Web インターフェース形式で結果を表示します。

よく使用されるプロファイルのタイプ：

Profile	測定内容	デフォルトで有効？
`profile`（CPU）	関数ごとの CPU 時間。1 秒に 100 回サンプリング	はい、リクエスト時
`heap`	ライブメモリと割り当て合計	はい
`allocs`	`heap` に似ていますが、デフォルトで割り当て合計を表示	はい
`goroutine`	現在のすべての goroutine のスタックトレース	はい
`block`	channel、`select`、`sync.Cond` での待機時間	いいえ
`mutex`	`sync.Mutex`/`RWMutex` の競合	いいえ
`trace`	詳細なイベントトレース（`go tool trace` で使用）	はい、リクエスト時

3. HTTP サービスで pprof を有効にする

最速の方法は、net/http/pprof をインポートしてサイドエフェクトを得ることです。このパッケージは、ハンドラー /debug/pprof/* を http.DefaultServeMux に登録します。

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof" // /debug/pprof/* を DefaultServeMux に登録
)

func main() {
	// 専用の pprof サーバー、localhost のみでリッスン
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	// アプリケーションサーバーは別の mux を使用、pprof は公開されない
	appMux := http.NewServeMux()
	appMux.HandleFunc("GET /invoice", invoiceHandler)
	log.Fatal(http.ListenAndServe(":8080", appMux))
}

注意すべき点がいくつかあります：

行 _ "net/http/pprof" はハンドラーを登録するだけで、このパッケージ内の関数は呼び出しません。
pprof サーバーはハンドラーとして nil を渡します。これは DefaultServeMux を使用することを意味し、ここに pprof ルートが含まれています。
メインアプリケーションは独自の appMux を使用するため、ポート 8080 には /debug/pprof がありません。

クイックチェック：

curl -s http://localhost:6060/debug/pprof/ | head -n 20

注意： /debug/pprof を Internet に公開しないでください。このエンドポイントはスタックトレースとコード構造を公開します。攻撃者はそれを使用してサービスを過負荷にする可能性があります（30 秒の CPU プロファイルはリソースを消費します）。localhost にバインドするか、プライベートネットワークと認証レイヤーの後ろに配置します。

4. CPU プロファイルの収集と読み取り

次のような請求書を生成する関数を持つサービスを想像してください：

type Item struct {
	SKU   string
	Price float64
	Qty   int
}

type Order struct {
	ID    int
	Items []Item
}

func BuildInvoice(o Order) string {
	s := ""
	for _, it := range o.Items {
		s += fmt.Sprintf("%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return s
}

ループの各反復で、s += ... は新しい文字列を作成し、古いコンテンツ全体をコピーします。多くの行を持つ注文の場合、コストは O(n²) で増加します。

サービスが負荷を受けている間（例えば、hey または wrk を使用して /invoice にリクエストを送信している場合）、30 秒間 CPU プロファイルを収集します：

go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=30"

収集が完了したら、対話モードに入ります。top と入力します：

(pprof) top 8
Showing nodes accounting for 2.41s, 85.46% of 2.82s total
      flat  flat%   sum%        cum   cum%
     0.92s 32.62% 32.62%      0.92s 32.62%  runtime.memmove
     0.41s 14.54% 47.16%      1.38s 48.94%  runtime.concatstrings
     0.33s 11.70% 58.87%      0.33s 11.70%  runtime.memclrNoHeapPointers
     0.27s  9.57% 68.44%      0.71s 25.18%  runtime.mallocgc
     0.18s  6.38% 74.82%      0.52s 18.44%  fmt.(*pp).doPrintf
     0.13s  4.61% 79.43%      0.13s  4.61%  strconv.fmtF
     0.10s  3.55% 82.98%      2.47s 87.59%  main.BuildInvoice
     0.07s  2.48% 85.46%      0.21s  7.45%  runtime.scanobject

最も重要な 2 つの列の読み方：

flat：その関数直接にある CPU 時間。
cum（累積）：その関数の時間 プラス それが呼び出すすべての関数。

ここで main.BuildInvoice は flat は小さいですが、cum はほぼ 88% です。ほとんどの時間は memmove と concatstrings に費やされます。つまり、文字列の連結です。各行の詳細を見るには、list を使用します：

(pprof) list BuildInvoice
ROUTINE ======================== main.BuildInvoice in /app/invoice.go
     100ms      2.47s (flat, cum) 87.59% of Total
         .          .     18:func BuildInvoice(o Order) string {
         .          .     19:	s := ""
      10ms       10ms     20:	for _, it := range o.Items {
      90ms      2.46s     21:		s += fmt.Sprintf("%s x%d = %.2f\n", ...)
         .          .     22:	}

21 行目が犯人です。フレームグラフを見たい場合は、Web インターフェースを開きます：

go tool pprof -http=:8081 "http://localhost:6060/debug/pprof/profile?seconds=30"

ブラウザーは Top、Graph、Flame Graph、Source ビューを開きます。フレームグラフでは、ブロックが広いほど、より多くの CPU を消費します。

strings.Builder と fmt.Fprintf を使用した修正版：

func BuildInvoiceFast(o Order) string {
	var b strings.Builder
	b.Grow(len(o.Items) * 32) // 事前に予測、何度も grow を避ける
	for _, it := range o.Items {
		fmt.Fprintf(&b, "%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return b.String()
}

5. Heap プロファイル：誰がメモリを保持しているのか？

go tool pprof http://localhost:6060/debug/pprof/heap

ヒーププロファイルには 4 つの「サンプルインデックス」が含まれています。フラグ -sample_index でインデックスを選択します：

inuse_space（デフォルト）：最新の GC 時点で 生きている バイト数。メモリリークを見つけるのに使用します。
inuse_objects：生きているオブジェクト数。
alloc_space：プログラム実行以来 割り当てられた バイトの合計。GC の圧力を引き起こしている場所を見つけるのに使用します。
alloc_objects：割り当てられたオブジェクトの総数。

go tool pprof -sample_index=alloc_space http://localhost:6060/debug/pprof/heap

(pprof) top 3
      flat  flat%   sum%        cum   cum%
    1.84GB 91.20% 91.20%     1.84GB 91.20%  main.BuildInvoice
    0.12GB  5.95% 97.15%     0.12GB  5.95%  fmt.Sprintf
    0.03GB  1.49% 98.64%     0.03GB  1.49%  encoding/json.Marshal

結果は、BuildInvoice が合計 1.84GB を割り当てたことを示していますが、ライブメモリは非常に小さい可能性があります。これは GC が多くの作業を行う必要があることの兆候です。この状況は、セクション 4 の CPU プロファイルに表示される runtime.mallocgc と runtime.scanobject の量と一致します。

注意： ヒーププロファイルもサンプルデータです（デフォルトでは 512KB の割り当てごとに約 1 つのサンプル）。そのため、数値は推定値にすぎません。バイト単位で比較しないでください。比率を見てください。

6. Goroutine プロファイル：goroutine リークの検出

goroutine の数が増え続ける場合、go tool pprof を使用せずに、ブラウザーまたは curl で素早く確認できます：

curl -s "http://localhost:6060/debug/pprof/goroutine?debug=1" | head -n 15

goroutine profile: total 10432
10398 @ 0x43a5d6 0x4071c5 0x406d78 0x6b2f45 0x46c0e1
#	0x6b2f44	main.(*PaymentService).notify+0x64	/app/payment.go:57

10,398 個の goroutine が payment.go:57 でスタックしています。これはほぼ確実にリークです。バグの原因となるコードは通常、次のような形式です：

func (s *PaymentService) notify(ctx context.Context, p Payment) {
	result := make(chan error) // unbuffered
	go func() {
		result <- s.gateway.Send(p) // 誰も受け取らなければ永遠にスタック
	}()
	select {
	case err := <-result:
		log.Println(err)
	case <-ctx.Done():
		return // 内側の goroutine は放置される
	}
}

ctx が先に期限切れになると、誰も result を読まなくなるため、内部 goroutine は send 命令で永遠にスタックします。簡単な修正は、make(chan error, 1) を使用して、send 命令が決してブロックしないようにすることです。

debug=2 では、エンドポイントは各 goroutine の完全なスタックトレースを印刷します。待機時間付き（例：[chan send, 42 minutes]）。この情報はデッドロック調査時に非常に役立ちます。

7. Block と mutex プロファイル

これら 2 つのプロファイルは、コストがあるため、デフォルトでは無効です。それらは main で有効にします：

import "runtime"

func init() {
	// 平均的に 5 人に 1 人の mutex 競合イベントを記録
	runtime.SetMutexProfileFraction(5)
	// ブロックされた 10µs ごとに 1 つの block イベントをサンプリング
	runtime.SetBlockProfileRate(10_000)
}

その後、通常通りプロファイルを収集します：

go tool pprof http://localhost:6060/debug/pprof/mutex
go tool pprof http://localhost:6060/debug/pprof/block

Mutex プロファイルは、どのロックが goroutine を待ち行列にさせるかを示します。例えば、共有キャッシュ map[int]Customer を保護する sync.Mutex。Block プロファイルは、goroutine がどのチャネルまたは select で長く待機しているかを示します。

注意： SetBlockProfileRate(1) は すべての block イベントを記録します。このレベルはローカルデバッグにのみ適しています。本番環境では、より大きなレートを使用するか、一時的に有効にしてください。

8. ベンチマークからのプロファイリング

特定の関数については、最も簡潔な方法はベンチマークを書いて go test にプロファイルを生成させることです。以下のコードは b.Loop() を使用するため、Go 1.24 以降が必要です。

package main

import (
	"fmt"
	"testing"
)

func sampleOrder(n int) Order {
	items := make([]Item, n)
	for i := range items {
		items[i] = Item{SKU: fmt.Sprintf("SKU-%04d", i), Price: 19.99, Qty: i%5 + 1}
	}
	return Order{ID: 1, Items: items}
}

func TestBuildInvoiceFastMatchesOriginal(t *testing.T) {
	order := sampleOrder(200)
	if got, want := BuildInvoiceFast(order), BuildInvoice(order); got != want {
		t.Fatalf("出力が異なります:\n got=%q\nwant=%q", got, want)
	}
}

func BenchmarkBuildInvoice(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoice(order)
	}
}

func BenchmarkBuildInvoiceFast(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoiceFast(order)
	}
}

テスト TestBuildInvoiceFastMatchesOriginal は、最適化版が元のバージョンと同じ結果を出力することを確認します。このステップをスキップしないでください。最適化が間違った結果を出すと無意味です。ベンチマークをプロファイルと共に実行します：

go test -run='^$' -bench=BuildInvoice -cpuprofile=cpu.out -memprofile=mem.out

BenchmarkBuildInvoice-8        1543    772410 ns/op   6342817 B/op    1002 allocs/op
BenchmarkBuildInvoiceFast-8   19821     60318 ns/op     36472 B/op     504 allocs/op

strings.Builder を使用したバージョンは約 12 倍高速で、割り当ては約 170 倍少ないです。フラグ -run='^$' は通常のテストをスキップして、ベンチマークだけを実行します。ファイル cpu.out と mem.out は次のように開きます：

go tool pprof -http=:8081 cpu.out

9. runtime/pprof を使用した CLI プログラムのプロファイリング

1 回実行して終了するツール（例えば、注文インポートジョブ）については、runtime/pprof を直接使用します：

package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
)

func main() {
	cpuFile, err := os.Create("cpu.out")
	if err != nil {
		log.Fatal(err)
	}
	defer cpuFile.Close()

	if err := pprof.StartCPUProfile(cpuFile); err != nil {
		log.Fatal(err)
	}
	defer pprof.StopCPUProfile()

	importOrders("orders.csv") // メインワーク

	memFile, err := os.Create("mem.out")
	if err != nil {
		log.Fatal(err)
	}
	defer memFile.Close()
	runtime.GC() // 書き込み前に inuse 統計を更新
	if err := pprof.WriteHeapProfile(memFile); err != nil {
		log.Fatal(err)
	}
}

ここでよくある 2 つのエラー：

StartCPUProfile の後に log.Fatal または os.Exit を呼び出すと、defer がスキップされます。その場合、StopCPUProfile は実行されず、プロファイルファイルは空または破損しています。
WriteHeapProfile の前に runtime.GC() を忘れる。inuse_* 統計情報は GC 後にのみ更新されるため、プロファイルは古い状態を反映する可能性があります。

10. 2 つのプロファイルの比較

最適化後、気分に頼るのではなく、再度測定する必要があります。フラグ -diff_base は、古いプロファイルを新しいプロファイルから差し引きます：

go tool pprof -diff_base=cpu_before.out cpu_after.out

(pprof) top 3
      flat  flat%   sum%        cum   cum%
    -0.89s 31.56% 31.56%     -0.89s 31.56%  runtime.memmove
    -0.40s 14.18% 45.74%     -1.35s 47.87%  runtime.concatstrings
    -0.25s  8.87% 54.61%     -0.66s 23.40%  runtime.mallocgc

負の値は時間が減少したことを意味します。結果が意味を持つためには、2 つのプロファイルを同じ条件で収集する必要があります：同じ負荷、同じ期間、同じマシン。

さらに、Go 1.21 以降、CPU プロファイルは Profile-Guided Optimization（PGO） にも利用できます。本番環境から代表的な CPU プロファイルを収集し、main パッケージフォルダーに default.pgo という名前を付けます。その後、go build はそのプロファイルを自動的に使用してホットコードパスをインライン化して最適化します。改善は通常数パーセントの範囲であり、コード行を変更する必要はありません。

11. よくあるエラーと使用しない場合

プロファイルが短すぎるか、負荷がない。 CPU プロファイルは 100Hz でサンプリングします。サービスが低い場合に 2 秒間だけ収集すると、runtime とノイズだけが表示されます。
flat と cum を混同する。 cum が高い関数が必ずしも犯人ではありません。それはただ犯人を呼び出しているだけかもしれません。
inuse_space と alloc_space を混同する。 リークを見つけたい場合は inuse を見てください。GC の圧力を減らしたい場合は alloc を見てください。
CPU プロファイルで I/O を測定する。 goroutine がデータベースまたは HTTP を待機している時間は CPU を消費しないため、CPU プロファイルには表示されません。block プロファイル、go tool trace、または分散トレースを使用してください。
アプリケーションポートで pprof を公開する。 セクション 3 を再度確認してください。

注意： pprof は「どこが消費するのか」という質問に答え、「最適化すべきか」には答えません。エンドポイントが SLA に達し、関数が CPU の 2% のみを占める場合、より複雑に書き直すことは通常価値がありません。

12. 結論

この記事では、あなたは次のことを学びました：

localhost の専用サーバーで安全に net/http/pprof を有効にする；
top と list を使用して CPU プロファイルを読み、flat と cum の違いを理解する；
inuse_space と alloc_space を使用してヒーププロファイルを使用する；
debug=1 と debug=2 を通じて goroutine リークを検出する；
block と mutex プロファイルを有効にする；
ベンチマークと CLI プログラムからプロファイルを生成する；
-diff_base を使用して前後を比較する。

最も効果的なプロセスは依然として：測定 → ホットスポットを見つける → 修正 → 正しい動作を保つテストを書く → 再測定。標準ライブラリに組み込みの pprof があるため、始めるために何もインストールする必要はありません。

Go を pprof でプロファイリング: CPU、メモリ、goroutine のボトルネック検出

1. 概要

2. pprof とは何か、どのような種類のプロファイルがあるか

3. HTTP サービスで pprof を有効にする

4. CPU プロファイルの収集と読み取り

5. Heap プロファイル：誰がメモリを保持しているのか？

6. Goroutine プロファイル：goroutine リークの検出

7. Block と mutex プロファイル

8. ベンチマークからのプロファイリング

9. runtime/pprof を使用した CLI プログラムのプロファイリング

10. 2 つのプロファイルの比較

11. よくあるエラーと使用しない場合

12. 結論

同じトピックの記事

GoのHTTPサーバーのグレースフルシャットダウン

GoのencOding/jsonを使ってJSONを読み書きする

GoのWorker pool：goroutineの制限、結果の取得、安全なキャンセル

Go の構造体埋め込み：継承に代わるもの

Go の defer、panic、recover: いつ使う