これは KLab Advent Calendar 2016 23日目の記事です。
こんにちは。服部です。
KLabでは大阪オフィスでゲーム開発をしています。
23番手もやはり緊張します。今日はGoのpprofを使ってプロファイルする時の小ネタをいくつか紹介します。
前提
go tool pprofやnet/http/pprofパッケージの基本的な使い方は理解している前提で進めます。
Goのプロファイリング関連の情報は以下のようなドキュメントや記事を参考にしていただければ。
- Profiling Go Programs
- Package pprof
- Go pprof 入門編 (CPU Profile とコマンドラインツール) : KLabGames Tech Blog
- Go pprof 応用編 (CPU 以外のプロファイル) : KLabGames Tech Blog
- Go pprof マスター編 (pprof の仕組み) : KLabGames Tech Blog
ではさっそく。
その1: Goroutineダンプ結果をソートしたい
Goroutineのダンプ結果からどのGoroutineがスタックしてるかや増殖してるかを確認したいときがあります。その際に大量にダンプ結果があると「どのGoroutineが一番多いねん」みたいな状況になって、目grepからのGoroutine数の多い箇所を探すことがあると思います。
というような状況に陥ったら、おもむろにpporftools/sortgoroutine.pyを使います。
$ curl -s "http://127.0.0.1:8080/debug/pprof/goroutine?debug=1" | python sortgoroutine.py
スタックごとのGoroutineの多い順にソートして表示してくれます。
ただし、これはGo1.7.Xあたりから改善されプロファイルした時点で結果がソートされるようになりました。あぁスクリプトが無に帰りました。が、無駄にカラー表示(-cオプション)できたり、逆順でソート(-rオプション)できたり、キーワードマッチしたスタックだけ表示(-mオプション)したりできるので、まだ使う機会は残されていそうです。
キーワードマッチは「sync.Mutexにあたりをつけて解析したいねん」などのシチュエーションで便利に使えます。
以下はカラー表示の出力結果
その2: -list=. -baseオプション指定時の2つのプロファイル結果をいい感じに確認したい
常駐しているプログラムに対してプロファイルする際に、2つのプロファイル結果の差分を確認してメモリリークしていないかや、CPU使用率の変化を見ることがあると思います。
$ curl -s "http://127.0.0.1:8080/debug/pprof/heap" > heap1.dump
$ curl -s "http://127.0.0.1:8080/debug/pprof/heap" > heap2.dump
$ go tool pprof -list=. -base=heap1.dump TARGET_BINARY heap2.dump
で、この結果を見てみると、大きなプログラムだと以下のような結果が1万行くらい続いてしまいます。
Total: 541921065
ROUTINE ======================== bufio.(*Reader).ReadBytes in /usr/local/Cellar/go/1.7.1/libexec/src/bufio/bufio.go
21031 21031 (flat, cum) 0.0039% of Total
. . 426: n += len(full[i])
. . 427: }
. . 428: n += len(frag)
. . 429:
. . 430: // Copy full pieces and fragment in.
21031 21031 431: buf := make([]byte, n)
. . 432: n = 0
. . 433: for i := range full {
. . 434: n += copy(buf[n:], full[i])
. . 435: }
. . 436: copy(buf[n:], frag)
ROUTINE ======================== bufio.(*Reader).ReadString in /usr/local/Cellar/go/1.7.1/libexec/src/bufio/bufio.go
1231 22262 (flat, cum) 0.0041% of Total
. . 443:// it returns the data read before the error and the error itself (often io.EOF).
. . 444:// ReadString returns err != nil if and only if the returned data does not end in
. . 445:// delim.
. . 446:// For simple uses, a Scanner may be more convenient.
. . 447:func (b *Reader) ReadString(delim byte) (string, error) {
. 21031 448: bytes, err := b.ReadBytes(delim)
1231 1231 449: return string(bytes), err
. . 450:}
. . 451:
. . 452:// WriteTo implements io.WriterTo.
. . 453:func (b *Reader) WriteTo(w io.Writer) (n int64, err error) {
. . 454: n, err = b.writeBuf(w)
変化の大きいところから見たいのにどこから見ればええんやろかなどと考え、途方に暮れて「とりあえずたこ焼きでも食べよか」となってしまうことがあると思います。
というような状況に陥ったら、おもむろにpporftools/findbigdiff.pyを使います。
差分が大きい順にソートして表示してくれます。助かります。（以下は一部情報だけを表示しています。）
$ go tool pprof -list=. -base=heap1.dump TARGET_BINARY heap2.dump | python findbigdiff.py
ROUTINE ======================== (*O).sender in loop.go
0 266147439 (flat, cum) 49.11% of Total
. . 32:
. . 33:func (o *O) sender() {
. . 34: for {
. . 35: select {
. . 36: case in := <-r.c:
. 1120218 37: for id, obj := range r.GetList() {
. . 38: if check(id) {
. 265027221 39: make(hohoge)
. . 40: }
. . 41: }
. . 42: case <-r.s:
. . 43: return
. . 44: }
ROUTINE ======================== (*O).Run in loop.go
0 248870941 (flat, cum) 45.92% of Total
. . 154: ticker := time.NewTicker(d)
. . 155: for {
. . 156: select {
. . 157: case <-ticker.C:
. 3743758 158: for _, obj := range r.GetList() {
. . 159: g := obj.Get()
. 65537 160: t := g.GetNewObject()
. 394595 161: t.send(g)
. . 162: }
. . 163: }
解析が少し楽になりました。
その3: メモリ使用状況をもう少し見やすくしたい
メモリ使用状況をビジュアライズする仕組みとして、 -callgrindオプション指定でcallgrind形式でファイルを書き出して、解析することができます。
$ go tool pprof -callgrind -alloc_objects TARGET_BINARY heap1.dump > heap1.callgrind
$ qcachegrind heap1.dump # on MacOSX
便利です。
ただbrew install qt qcachegrind等で簡単にインストールできるのですが、「もう少し気軽に確認できないもんやろか」と思うことがあると思います。
というような状況に陥ったら、おもむろにpporftools/dot2treemapjson.pyを使います。
dot形式のファイルを元にTreeMap形式のグラフをWebブラウザから確認できます。-pオプションでリッスンポート番号を指定します。
$ curl -s "http://127.0.0.1:8080/debug/pprof/heap" > heap.dump
$ go tool pprof -dot -alloc_objects TARGET_BINARY heap.dump | python dot2treemapjson.py -p 9999
このスクリプト自体いくつかPythonのモジュールをインストールする必要があるので、The Go Blogで紹介されてるような画像形式のコールツリーと比べるとあまり便利にはなりませんでした。もう少し表示方法やインタラクティブな仕組みを改善する必要があるのかなと思いました。
最後に
秘伝のタレ的な小ネタ(スクリプト)をいくつか紹介しました。
こんなツール使わなくても標準で使えるよとかこんなツールあるよとか教えていただけるとありがたいです。
あなたの秘伝のタレもぜひ教えてくださいm(_ _)m