1. pprof の導入
ベンチマークがストップウォッチだとすれば、pprof はかなり執拗な会計係です。単に「この処理に 120 ms かかりました」と言うだけでなく、どの関数でそのミリ秒が「燃えた」のかを示そうとします。Go では pprof は go tool pprof というツールとして存在し、プログラムのプロファイルを解釈して表示します。基本的な流れはシンプルです: バイナリとプロファイルファイルを用意して、それを pprof に渡します。
心理的な準備も大事です: pprof は「速くしてくれる」と約束するのではなく、「どこが痛いかを見せる」と約束します。実際に直すのはあなたです: 余分なアロケーションを減らし、ホットループを書き換え、より適切なデータ構造を使います。(そう、時にはループ内の fmt.Sprintf を 1 つ消すだけで治ることもあります。2 時間歩いたあとに靴の中の小石を見つけるようなものです。)
2. go test でプロファイルを取得する
一番うれしい点は、始めるために main にプロファイリングを組み込んで補助コードを書く必要がないことです。テストやベンチマークでは、サポートはすでに go test に組み込まれています。go tool pprof で解析できるプロファイルを書き出すためのプロファイリングフラグがあります。
最小限の「リファレンス」コマンドは次のようになります。ベンチマークを実行しつつ、CPU プロファイルと memory プロファイルをファイルへ保存するようにします。runtime/pprof のドキュメントにある例です:
go test -bench . -cpuprofile cpu.prof -memprofile mem.prof
ここでは 2 つの微妙な、しかし非常に実用的な点を理解する必要があります。
1 つ目: プロファイルは、実際に実行された その実行 に対して書き込まれます。ベンチマークが短すぎると、プロファイルは「ノイズっぽく」なり、ほとんど役に立たないことがあります。
2 つ目: go test はフラグを書き換えてテスト用バイナリの起動を管理できますし、プロファイリングフラグ（coverage を除く）は通常、テスト用バイナリを近くに残します。解析時に使えるようにするためです。これは便利です。なぜなら pprof はしばしば関数名とソース行を表示するために、プロファイルとバイナリの両方 を必要とするからです。
CPU プロファイルと -cpuprofile
CPU プロファイルは「CPU 時間がどこへ行ったのか」に答えます。Go の CPU profiling はサンプリング方式です。実行中、プログラムはおよそ 1 秒に 100 回、「ほんの一瞬」止まり、現在実行中の goroutine のスタックを記録します（つまり、「今どこにいるかを撮影する」イメージです）。そのため CPU プロファイルは統計的です。最後のナノ秒まで完璧に正確であることは保証しませんが、ホットスポット を見つけるには非常に有効です。
見る対象を用意するために、学習用アプリケーションに結びつけましょう。たとえば、タスク一覧があり、CLI 用にきれいな表へレンダリングしたいとします（表形式の出力は以前に扱ったので、ここでは簡略化した文字列フォーマットを使います）。まずは意図的に「あまり賢くない」レンダリングを、ループ内の fmt.Sprintf で行います。そう、これは顕微鏡で釘を打つようなものです。理屈では可能ですが、コストについて文句は言わないでください。
package taskfmt
import "fmt"
type Task struct {
ID int
Title string
Done bool
}
func FormatLineSprintf(t Task) string {
return fmt.Sprintf("%d\t%v\t%s\n", t.ID, t.Done, t.Title)
}
一見すると無害に見えます。しかし、こうした行が何千もあり、それが「ホット」な場所にあるなら、fmt.Sprintf はかなり高くつく可能性があります（CPU 的にもメモリ的にも）。これは「雰囲気」で推測するのではなく、プロファイルで確認します。
Memory プロファイルと -memprofile
Memory プロファイル（今日の最小構成では heap プロファイル）は、「どこでメモリを割り当てているか、またはどこで保持しているか」に答えます。これは Go で特に重要です。余分なアロケーションは「メモリを使う」だけでなく、GC による追加作業の可能性も意味するからです。そして GC は、すでにご想像のとおり、無料ではありません（ただし“十分安い”ことを目指しています）。
go test は -memprofile で memory profile をファイルへ書き出せますし、pprof にはアロケーションの表示モード（たとえばオブジェクト数や量で見るなど）がある、というヒントもあります。これは表示ツールとしての pprof 側の機能です。
例を用意するために、もう 1 つ関数を追加しましょう。タスクに対する出力をすべて 1 本の大きな文字列にまとめます（CLI では普通です。stdout にまとめて出力します）。まずは「力ずく」で、文字列連結をループ内で行います。これは古典的なやり方です。動きますが、大量データでは多くの一時文字列を生むことがあります。
package taskfmt
func FormatAllConcat(tasks []Task) string {
out := ""
for _, t := range tasks {
out += FormatLineSprintf(t)
}
return out
}
タスクが多いと、out += ... はしばしば「新しい文字列を作って、古いものをコピーし、さらに新しい部分を追加する」という意味になります。コンパイラが助けてくれることもありますが、一般的には余分なアロケーション候補です。ここで memory プロファイルが特にわかりやすくなります。どのコードがゴミの工場になったのかを示してくれるからです。
再現可能な負荷のためのベンチマーク
再現性のある負荷シナリオが必要です。理想的なのはベンチマークです。制御可能で、繰り返し可能で、「手でボタンを押す」必要がありません。*_test.go に BenchmarkFormatAllConcat を追加します。ここでは “sink 変数” のトリックも使います。結果をどこかに代入して、コンパイラが「誰にも必要ない」と判断して捨ててしまわないようにするためです。
package taskfmt
import (
"strconv"
"testing"
)
var sink string
func BenchmarkFormatAllConcat(b *testing.B) {
tasks := make([]Task, 1000)
for i := range tasks {
tasks[i] = Task{ID: i + 1, Title: "task " + strconv.Itoa(i+1)}
}
b.ResetTimer()
for i := 0; i < b.N; i++ {
sink = FormatAllConcat(tasks)
}
}
これで、CPU とメモリの両方がかなりはっきり現れる「舞台」ができました。ここからが一番おもしろいところです。プロファイルを取って読み解きます。
3. go tool pprof でプロファイルを分析する
pprof の基本的な使い方は非常にシンプルです: go tool pprof binary profile。つまり通常は、ツールに バイナリ と プロファイルファイル を渡します。
テストやベンチマークをプロファイルするときも、プロセスは 2 つのレベルに分かれます。
第 1 レベルでは、go test にプロファイルの記録を依頼します。たとえば、コマンドの形式としては次のようになります:
go test -bench . -cpuprofile cpu.prof -memprofile mem.prof
第 2 レベルでは、そのプロファイルを pprof で開きます。非常によくある流れは、CPU プロファイルをテスト用バイナリと一緒に開くことです（go test が近くに残すことができます）。そうすると pprof が関数名を表示し、ソース行へ移動できるようになります。基本の考え方は同じです: go tool pprof <binary> <profile>。
pprof が起動すると、対話モードになります。(pprof) というプロンプトが表示され、そのあとでコマンドを入力します。ほぼ常に最初に役立つコマンドは top、top -cum、そして時々 list <func> です。
top と top -cum の読み方: hotspots、flat と cum
ここでの “hotspot” とは、コストに大きく寄与する場所、という単純な意味です。CPU プロファイルでは、「CPU 時間が燃えている場所」です。memory プロファイルでは、「メモリが燃えている場所」（多く割り当てられている、または多く保持されている場所）です。
topN コマンド（またはモードによっては単に top）は、最も寄与が大きい関数を表示します。Go のプロファイリングに関する古典的な記事では、top は関数の「自己時間」で並び替えられ、累積時間で並べるには -cum（cumulative）モードを使う、と説明されています。
出力を古代のルーン文字のように読まないために、列の意味を小さな表に分解しましょう（名前は少し違うことがありますが、意味は通常同じです）:
| Column | How to read it | Intuitive meaning |
|---|---|---|
|
“how much time or memory directly in this function” | the function itself “eats” the resource |
|
“how much time or memory in this function and everything it calls” | the function is the “entry to the meat grinder” |
|
share of the total | how important it is in the overall picture |
では、実践的な読み方です。top の上位に runtime.* や fmt.* が出てきても、「runtime を最適化しろ」という意味ではありません。あなたのコードが runtime や fmt に大量の仕事をさせた、という意味です。多くの場合、次の正しい一歩は、ループ内で fmt.Sprintf を呼んでいるあなたの関数を見つけて、それを書き換えることです。
pprof のミニセッション: top、top -cum、list
pprof の対話性は最初は「ただのコンソール」に見えますが、実際には非常に便利です。問題へ素早く“近づく”ことができます。たとえば、ロジックは次のようになります（コマンドはシナリオの説明であり、“課題”ではありません）:
go tool pprof <binary> cpu.prof
(pprof) top
(pprof) top -cum
(pprof) list FormatAllConcat
これが機能する理由です。top は hotspots の候補を表示します。top -cum は、多くの時間が通過する“親”関数を見つけるのに役立ちます。そして list は注釈付きのソースを表示します。つまり、関数内のどの行がサンプルにより頻繁に現れたかがわかります。まさにこの「topN で見て、その後 -cum で掘る」アプローチは公式の記事にもあります。topN はサンプル上位を示し、-cum は累積時間で並べ替えます。
そして、pprof のコマンドとオプションは平均的なビデオゲームより多いですが、基本セットだけでもすでに 80% の価値があります。
4. プロファイルに基づく改善と正しい解釈
最適化のための最適化は悪い習慣です（寝るためにエナジードリンクを飲むようなものです）。しかし、プロファイルに基づく最適化はまともなエンジニアリングです。実際に熱い場所を直します。
今回の例では、疑わしい箇所はすでに明らかです。ループ内の文字列連結と fmt.Sprintf です。「小さい文字列から大きい文字列を作る」ための最も典型的な修正は strings.Builder です。これは文字列と strings パッケージの話で既に知っているので、今回はそのまま実用的に使います。
package taskfmt
import "strings"
func FormatAllBuilder(tasks []Task) string {
var b strings.Builder
for _, t := range tasks {
b.WriteString(FormatLineSprintf(t))
}
return b.String()
}
これで中間文字列の数を減らせるかもしれません。しかし、まだループ内で fmt.Sprintf を使っています。プロファイルでかなりの割合が fmt に行っているなら、次のステップはホットな場所での Sprintf をやめ、builder にもっと直接書き込むことです（たとえば strconv.AppendInt を []byte に対して使うなど）。ただし、これは少し高度で、学習プロジェクトですぐに必要とは限りません。大事なのは、pprof が「たぶん」ではなく「ここに寄与がある」というレベルで判断を助けてくれることです。
CPU vs memory: プロファイルの意味を混同しない
2 種類のプロファイルを初めて見ると、「同じものについて言っている」と思いがちです。実際には、答える質問が違います。
CPU プロファイルは、プログラムが実際にどこで実行されていたかを示します（実行サンプルに基づいています）。
Memory プロファイルは、どこでアロケーションが起きているか、または heap がどのように使われているかを示します（つまり、GC への圧力がどこで増えるかがわかります）。
非常に現実的なシナリオとして、CPU の hotspot と memory の hotspot が別の場所になることがあります。たとえば、CPU はパースや文字列比較に消え、メモリはログ出力やフォーマットに流れていく、という具合です。あるいは逆に、CPU は一見「普通」でも、メモリが異常に多く割り当てられて GC がより頻繁に動き、その結果として CPU も二次的に燃え始めます。
だから、正しい習慣はこうです: 「遅い」が気になるなら CPU から始めます。「メモリを食う」「GC がうるさい」が気になるなら memory を見ます。全部気になるなら、おめでとうございます。もうほぼ本番環境です。
go tool pprof が Go のバージョンに対応していることが重要な理由
最後に、互換性についての重要な注意です。Go のソースには、はっきりと「特定の Go リリースに付属しているものが確実に動作する」と書かれています。つまり、Go に同梱される go tool pprof は、同じバージョンのプログラムのプロファイルとの互換性についてテストされています。
これは「別の方法はだめ」という意味ではありません。意味するのは、インターネットから適当な pprof を入れたり、直接 github.com/google/pprof を引いてきたりして変な問題が出た場合、それは「Go が壊れた」のではなく、「推奨ルートから外れた」ということです。学習プロジェクトでは go tool pprof に従うのがいちばん落ち着いた道です。
5. pprof を使うときの典型的なミス
ミス 1: あまりに短い実行でプロファイルを取り、ノイズに驚く。
Go の CPU プロファイルはサンプリングです。ベンチマークが「ほぼ瞬時」に終わると、統計が貧弱になり、top に偶然のスパイクが出ることがあります。こういう場合は通常、負荷をより長くする（たとえばベンチマークがある程度の時間走るようにする）と、プロファイルの比較がしやすくなります。
ミス 2: setup がプロファイルに入ってしまい、思っていたものを測れていない。
測定対象のループ内でテストデータを作ったり、ファイルを読んだり、ログを出したり、rand.New(...) を使ったりすると、プロファイルはそのままそれを示します。そのあとでお決まりの流れになります: 「pprof は strconv.Itoa が熱いと言っているけど、僕はソートを最適化したんだが!」 だから、データ準備は測定部分から厳密に分離してください。ベンチマークで既にやったのと同じです。
ミス 3: 適切なバイナリなしでプロファイルを開き、コンテキストを失う。
pprof はバイナリを見ると特に有用です。そうすると、サンプルを関数やソース行に対応付けられるからです。さらに、go test はプロファイル用に（coverage を除いて）通常テスト用バイナリを残すので、同じバイナリと一緒に分析できます。バイナリが一致しない場合（別ビルド、別バージョン、別コード）には、出力がわかりにくくなることがあります。
ミス 4: top の runtime.* に固執し、“ランタイムを最適化しよう”とする。
一覧の上位に runtime.mallocgc や fmt 関連の何かが出てきたら、それはほぼ常にあなたのコードの症状です。つまり、アロケーションが多い、フォーマットが多い、型変換が多すぎる、データ構造が悪い、ということです。普通はランタイムにパッチを当てるのではなく、その負荷を減らします。中間オブジェクトを減らし、ループを単純にし、文字列の扱いを丁寧にします。
ミス 5: top（flat）だけを見て、問題への“入口”を見逃す。
ある関数は自分ではほとんど仕事をしなくても、コストの高い処理の連鎖を呼び出していることがあります。top の flat では低くても、top -cum では高いことがあります。-cum モードは、主要なコストが「どこを通っているか」を見るためにこそ必要です。このアプローチ（そして cumulative ソートの意味）は、Go のプロファイリングに関する公式記事でも示されています。
GO TO FULL VERSION