概要
前回
にてpprofの基本的な使い方を説明しました。
今回はさらに詳細に調べるためのコマンドラインツールの使い方を説明します。
環境
- golang 1.11.0
プロファイルの取得
今回はnet/http/pprofの方で検証します。
サンプルコード
今回もCPUバウンドなフィボナッチ数を使います。
import ( "fmt" "log" "net/http" _ "net/http/pprof" ) func fib(n int) int { if n < 2 { return n } return fib(n-1) + fib(n-2) } func main() { go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() fmt.Println("start") for { fib(27) fib(28) fib(29) } }
プロファイル
プロファイル用のファイルを生成します。
$ go tool pprof http://localhost:6060/debug/pprof/profile Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile Saved profile in /Users/jun06t/pprof/pprof.samples.cpu.001.pb.gz Type: cpu Time: Oct 11, 2018 at 12:47pm (JST) Duration: 30.20s, Total samples = 26.90s (89.06%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
この状態で進めても良いですし、/Users/jun06t/pprof/pprof.samples.cpu.001.pb.gzというファイルが生成されたのでそれを使って
$ go tool pprof main /Users/jun06t/pprof/pprof.samples.cpu.001.pb.gz File: main Type: cpu Time: Oct 11, 2018 at 12:47pm (JST) Duration: 30.20s, Total samples = 26.90s (89.06%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
としても良いです。.gzのままで出来ます。
コマンドラインツール
top
通常
通常の使い方です。一番良く使いますね
(pprof) top Showing nodes accounting for 26.78s, 99.55% of 26.90s total Dropped 1 node (cum <= 0.13s) flat flat% sum% cum cum% 25.44s 94.57% 94.57% 25.44s 94.57% main.fib 1.11s 4.13% 98.70% 1.11s 4.13% runtime.newstack 0.22s 0.82% 99.52% 0.22s 0.82% runtime.nanotime 0.01s 0.037% 99.55% 0.35s 1.30% runtime.sysmon 0 0% 99.55% 25.44s 94.57% main.main 0 0% 99.55% 25.44s 94.57% runtime.main 0 0% 99.55% 1.11s 4.13% runtime.morestack 0 0% 99.55% 0.35s 1.30% runtime.mstart 0 0% 99.55% 0.35s 1.30% runtime.mstart1
top n
上位n件を表示します
(pprof) top 2 Showing nodes accounting for 26.55s, 98.70% of 26.90s total Dropped 1 node (cum <= 0.13s) Showing top 2 nodes out of 9 flat flat% sum% cum cum% 25.44s 94.57% 94.57% 25.44s 94.57% main.fib 1.11s 4.13% 98.70% 1.11s 4.13% runtime.newstack
peek
特定の関数に対して、呼び出し元がどこか・どれくらいcallしているかを知りたい時に使えます。
例えば正規表現の関数が重いけど、どこの呼び出しが重いのかが分からない、といった時などに使えますね。
list 関数名
の順に指定します。
ちょっとサンプルコードだとシンプルすぎて分かりにくいので、
func someCaller(n int) { fib(n) } func main() { go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() fmt.Println("start") for { fib(27) someCaller(28) fib(29) } }
のようにいじってから実行します。
ではfib()がどこからどれくらい呼ばれるかを調べてみましょう。
(pprof) peek fib Showing nodes accounting for 26.66s, 100% of 26.66s total ----------------------------------------------------------+------------- flat flat% sum% cum cum% calls calls% + context ----------------------------------------------------------+------------- 16.93s 68.21% | main.main 7.89s 31.79% | main.someCaller 24.82s 93.10% 93.10% 24.82s 93.10% | main.fib ----------------------------------------------------------+-------------
このようにsomeCallerからの呼び出しとmainからの直接呼び出しの頻度やかかった時間が分析できます。
list
listはソースコードの各行がどれくらい時間がかかっているか、どれくらいリソースを使っているかなどが分かるコマンドです。
注意としてlistにはソースコードを必要とします。
なのでこのバイナリのソースが入っているディレクトリ内で実行してください。
特定の関数を調査したい
list 関数名
と実行します。引数は関数です。
例えばfib()が重いのでfib関数を詳しく調べたい、となれば
(pprof) list fib Total: 26.90s ROUTINE ======================== main.fib in /Users/a13156/.go/src/github.com/jun06t/golang-practice/pprof/net/main.go 25.44s 39s (flat, cum) 144.98% of Total . . 6: "net/http" . . 7: . . 8: _ "net/http/pprof" . . 9:) . . 10: 7.36s 7.36s 11:func fib(n int) int { 3.82s 3.82s 12: if n < 2 { 2.38s 2.38s 13: return n . . 14: } 11.88s 25.44s 15: return fib(n-1) + fib(n-2) . . 16:} . . 17: . . 18:func main() { . . 19: go func() { . . 20: log.Println(http.ListenAndServe("localhost:6060", nil))
として、関数内のどこで時間がかかっているかわかります。
特定のパッケージの全関数を調査したい
もしくは
list パッケージ名.
としてそのパッケージで利用してる関数を全て表示させます。
main.とすればmainパッケージの関数をすべて指定することができます。
(pprof) list main. Total: 26.90s ROUTINE ======================== main.fib in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/net/main.go 25.44s 39s (flat, cum) 144.98% of Total . . 6: "net/http" . . 7: . . 8: _ "net/http/pprof" . . 9:) . . 10: 7.36s 7.36s 11:func fib(n int) int { 3.82s 3.82s 12: if n < 2 { 2.38s 2.38s 13: return n . . 14: } 11.88s 25.44s 15: return fib(n-1) + fib(n-2) . . 16:} . . 17: . . 18:func main() { . . 19: go func() { . . 20: log.Println(http.ListenAndServe("localhost:6060", nil)) ROUTINE ======================== main.main in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/net/main.go 0 25.44s (flat, cum) 94.57% of Total . . 20: log.Println(http.ListenAndServe("localhost:6060", nil)) . . 21: }() . . 22: . . 23: fmt.Println("start") . . 24: for { . 4.87s 25: fib(27) . 7.79s 26: fib(28) . 12.78s 27: fib(29) . . 28: } . . 29:}
大体のケースではmain.を指定すればどこが重いのか見れると思います。
注意
最初にソースが必要といいましたが、実際はフルパスを参照するため別のサーバでビルドしたやつを持ってきたりした場合はローカルのソースとフルパスが異なるせいでno such file or directoryで怒られることがあります。
なので理想を言えばビルドマシン上で実行するのが確実です。
裏技的にはその関数・パッケージのソースコードがある場所にバイナリを置いてgo tool pprofすればエラーにならず解析できます。
例：gopkg.in/mgo.v2/bson.(*decoder).readStrが重たい場合
先程の使い方だとlist readStrしたいです。
この場合バイナリをmain関数の場所ではなく/vendor/gopkg.in/mgo.v2/bson/に入れて
$ go tool pprof バイナリ プロファイリングファイル
としてlist readStrを実行すると
(pprof) list readStr Total: 5.61GB ROUTINE ========================xxxx/vendor/gopkg.in/mgo.v2/bson.(*decoder).readStr in xxxx/vendor/gopkg.in/mgo.v2/bson/decode.go 2.07GB 2.07GB (flat, cum) 36.97% of Total . . 771: l := d.readInt32() . . 772: b := d.readBytes(l - 1) . . 773: if d.readByte() != '\x00' { . . 774: corrupted() . . 775: } 2.07GB 2.07GB 776: return string(b) . . 777:} . . 778: . . 779:func (d *decoder) readCStr() string { . . 780: start := d.i . . 781: end := start
このように表示できます。
よくやるプロファイリング手順
- 本番サーバでプロファイリング用のファイルを生成する
- ローカルに本番のバイナリと↑のファイルをダウンロード。
- ↑をソースコードのディレクトリに置く
- go tool pprofでプロファイリング開始
- topでどの関数が重いのか見る
- listで具体的なコードの問題箇所を見つける
この手順で調査することが多いと思います。
