Go で利用できるプロファイリングツール pprof の読み方


# 概要
Go にはプロファイリングツールがついているのだけど，何を出力してくれているのかよく分からなかったのでメモ．間違いに気づかれた方いらっしゃったらコメントいただければ幸いです :bow:．

# 出典
Russ Cox さんが下記に書いてくれてました．これを読むのが間違いないです．

* Russ Cox, [Profiling Go Programs](http://blog.golang.org/profiling-go-programs)

# CPU Profiling

## プロファイリング用のコードの埋め込み

まず， `runtime/pprof` を import しておきます．(`net/http/pprof`というのもあります)．

CPU Profiling は計測したい実行コードの前で`StartCPUProfile()`を呼んで，計測終了のタイミングで`pprof.StopCPUProfile()`を呼びます．終了の方は defer に登録しておけば関数抜けるときに自動で呼ばれるので便利ですが，`Ctr-C`とかで終了させなきゃいけない場合にはこれだとうまくいきません．プロファイル結果はファイルに出力されます．

```go:CPUProfile
func main() {
   cpuprofile := "mycpu.prof"
   f, err := os.Create(cpuprofile)
   if err != nil {
       log.Fatal(err)
   }
   pprof.StartCPUProfile(f)
   defer pprof.StopCPUProfile()
```

```go:CPUProfile_Ctr-Cで終了してしまうようなときのサンプル
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
% go build myprog; ./myprog
```

プロファイリングツール `pprof` を実行します．引数に設定するのは，ビルドした実行ファイルと，プロファイル結果の出力です．

```go:pprof
% go tool pprof myprog mycpu.prof
```

プロファイリングが起動するので，ここでコマンドを入力してやると結果が見られます．`topN` とコマンドすると，上位`N`件が表示され，こんな感じになります（下記は[Profiling Go Programs](http://blog.golang.org/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回サンプリングがおこなわれたことが分かります．

1. 最初のカラムは，サンプリング中に何回その関数が実行されていたかを表していて，たとえば，一番上の `runtime.mapaccess1_fast64` は2525回のサンプリング中，298回カウントされたとこと示しています．
2. 2番目のカラムは実行中の関数がカウントされた割合で，298/2525=11.8% といいう意味です．
3. 3番目のカラムは，その行までの2番目のカラムの合計です．要するに割合の累計です．
4. 4番目のカラムは実行中，もしくは呼び出した関数を待っている状態の関数のカウントです．上の例の2行目の`main.FindLoops`は、サン​​プルの10.6％で実行されていたが，サンプルの84.1％に実行中か，呼び出した関数を待っている状態の実行がコールスタックにあった （という意味らしいです）
5. 5番目のカラムは4番目のカラムの割合．

という感じのようです．4,5 番目のカラムで結果をソートするには，`-cum` オプションをつければいいです．この例も[Profiling Go Programs](http://blog.golang.org/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](http://www.graphviz.org/)をインストールしておく必要があります．**
**[graphviz](http://www.graphviz.org/)をインストールしておく必要があります．** 大事なことなので2回言いました．