Go
pprof

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

More than 3 years have passed since last update.


概要

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


出典

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


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回サンプリングがおこなわれたことが分かります.


  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からの引用です.

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