概要
Go にはプロファイリングツールがついているのだけど，何を出力してくれているのかよく分からなかったのでメモ．間違いに気づかれた方いらっしゃったらコメントいただければ幸いです 
．
出典
Russ Cox さんが下記に書いてくれてました．これを読むのが間違いないです．
- Russ Cox, Profiling Go Programs
CPU Profiling
プロファイリング用のコードの埋め込み
まず， runtime/pprof を import しておきます．(net/http/pprofというのもあります)．
CPU Profiling は計測したい実行コードの前でStartCPUProfile()を呼んで，計測終了のタイミングでpprof.StopCPUProfile()を呼びます．終了の方は defer に登録しておけば関数抜けるときに自動で呼ばれるので便利ですが，Ctr-Cとかで終了させなきゃいけない場合にはこれだとうまくいきません．プロファイル結果はファイルに出力されます．
func main() {
cpuprofile := "mycpu.prof"
f, err := os.Create(cpuprofile)
if err != nil {
log.Fatal(err)
}
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
func main() {
cpuprofile := "mycpu.prof"
f, err := os.Create(cpuprofile)
if err != nil {
log.Fatal(err)
}
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()
c := make(chan os.Signal, 1)
signal.Notify(c, os.Interrupt)
go func() {
for sig := range c {
log.Printf("captured %v, stopping profiler and exiting...", sig)
pprof.StopCPUProfile()
os.Exit(1)
}
}()
使い方
プロファイリング用のコードを埋め込んだプログラムをビルドして実行するとプロファイル結果が出力されます（というか，プロファイル結果を出力するようにコードを埋め込みました）．mycpu.prof というファイルが出力されるとします．
% go build myprog; ./myprog
プロファイリングツール pprof を実行します．引数に設定するのは，ビルドした実行ファイルと，プロファイル結果の出力です．
% go tool pprof myprog mycpu.prof
プロファイリングが起動するので，ここでコマンドを入力してやると結果が見られます．topN とコマンドすると，上位N件が表示され，こんな感じになります（下記はProfiling Go Programsより引用）
(pprof) top10
Total: 2525 samples
298 11.8% 11.8% 345 13.7% runtime.mapaccess1_fast64
268 10.6% 22.4% 2124 84.1% main.FindLoops
251 9.9% 32.4% 451 17.9% scanblock
178 7.0% 39.4% 351 13.9% hash_insert
131 5.2% 44.6% 158 6.3% sweepspan
119 4.7% 49.3% 350 13.9% main.DFS
96 3.8% 53.1% 98 3.9% flushptrbuf
95 3.8% 56.9% 95 3.8% runtime.aeshash64
95 3.8% 60.6% 101 4.0% runtime.settype_flush
88 3.5% 64.1% 988 39.1% runtime.mallocgc
プロファイリングは，1秒間に100回程度プログラムを停止させ，そのときのスタックの状態から動作しているメソッドをサンプリングするような仕組みのようです．上の例では，2525回サンプリングがおこなわれたことが分かります．
- 最初のカラムは，サンプリング中に何回その関数が実行されていたかを表していて，たとえば，一番上の
runtime.mapaccess1_fast64は2525回のサンプリング中，298回カウントされたとこと示しています． - 2番目のカラムは実行中の関数がカウントされた割合で，298/2525=11.8% といいう意味です．
- 3番目のカラムは，その行までの2番目のカラムの合計です．要するに割合の累計です．
- 4番目のカラムは実行中，もしくは呼び出した関数を待っている状態の関数のカウントです．上の例の2行目の
main.FindLoopsは、サンプルの10.6％で実行されていたが，サンプルの84.1％に実行中か，呼び出した関数を待っている状態の実行がコールスタックにあった （という意味らしいです） - 5番目のカラムは4番目のカラムの割合．
という感じのようです．4,5 番目のカラムで結果をソートするには，-cum オプションをつければいいです．この例もProfiling Go Programsからの引用です．
(pprof) top5 -cum
Total: 2525 samples
0 0.0% 0.0% 2144 84.9% gosched0
0 0.0% 0.0% 2144 84.9% main.main
0 0.0% 0.0% 2144 84.9% runtime.main
0 0.0% 0.0% 2124 84.1% main.FindHavlakLoops
268 10.6% 10.6% 2124 84.1% main.FindLoops
おまけ
これらの数値をグラフ化してかっこよく見ることが可能です．
(pprof) web
とするだけ！
ただし，graphvizをインストールしておく必要があります．
graphvizをインストールしておく必要があります． 大事なことなので2回言いました．