概要

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

出典

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

Russ Cox, Profiling Go Programs

CPU Profiling

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

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

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

CPUProfile

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

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 というファイルが出力されるとします．

build

% go build myprog; ./myprog

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

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回言いました．

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

概要

出典

CPU Profiling

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

使い方

おまけ