こんにちは、現場の最前線でシステムの「心音」を聴き続けているリードチーフエンジニアです。
Go言語(Golang)を選んだあなたは、非常に賢明な選択をしました。Goはシンプルで高速、そして並行処理に強い。しかし、開発を進めていくと、必ずと言っていいほど「不可解な壁」にぶつかります。
「コードは完璧なはずなのに、なぜか時々レスポンスが100ミリ秒以上遅れる」
「CPU使用率は高くないのに、処理が詰まっている気がする」
こうした「数値化しにくい停滞」の正体は、アプリケーションの外側ではなく、Goの「ランタイム(実行環境)」というブラックボックスの中で起きています。今日は、そのブラックボックスをこじ開け、中身を手に取るように可視化する究極の武器、『ランタイム・トレース解析(go tool trace)』の世界へお連れしましょう。
これをマスターすれば、あなたはただの「コードを書く人」から、システムの挙動をミリ秒単位で支配する「真のエンジニア」へと進化できるはずです。
—
1. なぜ「pprof」ではなく「trace」が必要なのか?
多くのエンジニアは、パフォーマンス分析に `pprof` を使います。確かに `pprof` は「どこがCPUを多く使っているか」を知るには最適です。しかし、「なぜ何もしていない時間があるのか」は教えてくれません。
- pprof: サンプリング(点)の記録。「どの関数が重いか」を知るためのもの。
- trace: イベント(線)の記録。「いつ、どのGoroutineが、なぜ止まったか」を知るためのもの。
マイクロサービスのスパイク(一時的な遅延)の多くは、計算が重いのではなく、「待ち」が原因です。ガベージコレクション(GC)による停止、スケジューラの割り当て待ち、ネットワークIOの待機。これらを可視化できるのが `trace` です。
—
2. 【準備】トレースを取得するための「魔法の一行」
まずは、あなたのプログラムから実行データを書き出す準備をしましょう。Goには標準で `runtime/trace` という強力なパッケージが備わっています。
もっとも基本的な、ファイルにトレースを書き出す実装を見てみましょう。
package main
import (
“os”
“runtime/trace”
“log”
)
func main() {
// 1. トレースログを保存するファイルを作成
f, err := os.Create(“trace.out”)
if err != nil {
log.Fatalf(“トレースファイルの作成に失敗: %v”, err)
}
defer func() {
// プログラム終了時に確実にファイルを閉じる
if err := f.Close(); err != nil {
log.Fatalf(“ファイルのクローズに失敗: %v”, err)
}
}()
// 2. トレースの開始
// これ以降の全イベント(Goroutineの生成、破棄、GC、システムコール等)が記録されます
if err := trace.Start(f); err != nil {
log.Fatalf(“トレースの開始に失敗: %v”, err)
}
defer trace.Stop() // 3. 終了時に記録を止める
// — ここに解析したいメイン処理を書く —
runYourBusinessLogic()
// ————————————
}
実務のマイクロサービスであれば、HTTPエンドポイント経由で `net/http/pprof` を使って動的に取得するのが一般的ですが、まずはこの「ファイルに書き出す」という基本を身体に叩き込んでください。
—
3. 実演:わざと「スパイク」を発生させて解析する
理論だけではつまらないですね。大量のメモリ割り当てを行い、GC(ガベージコレクション)を誘発させてシステムをわざと停滞させるコードを動かしてみましょう。
実験コード (main.go)
package main
import (
“fmt”
“os”
“runtime/trace”
“time”
)
func main() {
f, _ := os.Create(“trace.out”)
defer f.Close()
trace.Start(f)
defer trace.Stop()
fmt.Println(“解析開始…”)
// 重い処理をシミュレート
for i := 0; i < 5; i++ {
go work(i)
}
time.Sleep(3 time.Second)
fmt.Println("解析終了。 'go tool trace trace.out' を実行してください。")
}
func work(id int) {
for {
// 大量の小さなスライスを生成してメモリに負荷をかける
// これにより頻繁なGC(ガベージコレクション)が発生する
sink := make([]byte, 1<<20) // 1MB
if len(sink) == 0 {
break
}
time.Sleep(10 time.Millisecond)
}
}
トレースの実行と可視化
コードを実行して `trace.out` が生成されたら、いよいよ魔法のコマンドを打ち込みます。
プログラムを実行してバイナリデータを生成
go run main.go
Go標準の解析ツールを起動
go tool trace trace.out
コマンドを打つと、ローカルサーバーが立ち上がり、ブラウザが自動的に開きます。そこで 「View trace」 をクリックしてください。
—
4. プロの視点:トレース画面のどこを見るべきか?
ブラウザに表示された複雑なタイムラインを見て、圧倒されないでください。私たちが注目すべきは、たったの3点です。
① Goroutines: 実行待ちの列を見て、並列度を知る
画面上部の「Goroutines」セクションを見てください。
- Runnable (緑): 動きたいのにCPUが空くのを待っている状態。ここが分厚い場合、`GOMAXPROCS`(使用CPUコア数)の設定が最適でないか、処理を詰め込みすぎです。
- Running (濃い緑): 実際に動いている状態。
② Heap: メモリの階段を見て、GCの衝撃を知る
「Heap」セクションのグラフがノコギリの歯のように急上昇し、一気にガクンと落ちている場所を探してください。
- 落ちているタイミングで 「GC (Garbage Collection)」 というバーが全スレッドに渡って出現していませんか?
- これが「Stop The World (STW)」です。この間、あなたの書いたビジネスロジックは1ミリ秒も動いていません。スパイクの正体は、大抵ここです。
③ Network Wait / Syscall: 外部要因の停滞
もしCPUもメモリも余裕があるのに処理が遅いなら、Goroutineが「Network Wait」の状態になっていないか確認してください。DBのレスポンス待ちや外部APIの遅延が、視覚的な「空白の時間」として現れます。
—
5. 現場で震えるほど役立つ「改善のヒント」
トレースを解析した結果、もしあなたが「GCによる停滞」を見つけたらどうすべきか。私なら、若手エンジニアにこうアドバイスします。
1. ポインタの多用を避ける:
GoのGCはポインタを追いかけます。構造体を値渡しにする、あるいは小さなオブジェクトを大量に作らず `sync.Pool` で再利用するだけで、トレース上のGCの山は劇的に低くなります。
2. 事前割り当て(Pre-allocation):
`make([]int, 0, 1000)` のように、スライスの容量(capacity)をあらかじめ指定してください。動的な拡張によるメモリ再割り当てを防ぐだけで、ランタイムの負荷は激減します。
3. Goroutineのリークを疑う:
「Goroutines」の数が右肩上がりで減っていないなら、どこかで終了していないGoroutineがいます。それはメモリを食いつぶし、最終的にランタイム全体のパフォーマンスを蝕みます。
—
結びに代えて:アーキテクトへの第一歩
`go tool trace` は、いわば「Go専用のレントゲン写真」です。
表面上のエラーログだけを見て悩むのはもう終わりにしましょう。ランタイムの中で何が起きているのかを可視化できれば、パフォーマンスチューニングは「勘」ではなく「科学」になります。
最初は複雑に見えるかもしれません。しかし、自分で書いたコードが、OSのスレッド上でどう動き、GCにどう邪魔され、そしてどう実行されているのかを一度でも目にすれば、あなたのコーディングの質は今日から劇的に変わります。
さあ、今すぐ自分のプロジェクトで `trace.out` を出力してみてください。そこには、あなたがまだ知らない「自分のコードの真の姿」が隠されているはずです。
健闘を祈ります!