Carpe Diem

備忘録

Golangのpprofの使い方【コマンドラインツール編】

概要

前回

christina04.hatenablog.com

にてpprofの基本的な使い方を説明しました。

今回はさらに詳細に調べるためのコマンドラインツールの使い方を説明します。

環境

プロファイルの取得

今回は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

このように表示できます。

よくやるプロファイリング手順

  1. 本番サーバでプロファイリング用のファイルを生成する
  2. ローカルに本番のバイナリと↑のファイルをダウンロード。
  3. ↑をソースコードディレクトリに置く
  4. go tool pprofでプロファイリング開始
  5. topでどの関数が重いのか見る
  6. listで具体的なコードの問題箇所を見つける

この手順で調査することが多いと思います。

ソース