このエントリーは、 KLab Advent Calendar 2015 の17日目の記事です。

pprof は Go の標準ライブラリにあるプロファイラです。

CPUを使用している部分を見つけるだけでなく、CPUを使ってないのにレイテンシが悪化するケースやメモリリークを発見したり、長時間安定して動くサーバープログラムを開発するのにとても便利です。

今日から3日間の連載でこの pprof の使い方や仕組みについて見て行きます。最初は一番基本となる CPU プロファイルの取得方法と、 go tool pprof の使い方を説明します。

Note: Macでの注意点

Mac OS X の Mavericks 以前は、 Go の CPUProfiler が利用している SIGPROF シグナルに問題があり、 CPU プロファイルを取るためにカーネルにパッチを当てる必要がありました。
この問題は El Capitan で解決されています。 El Capitan にアップデートできない人は、 https://github.com/rsc/pprof_mac_fix を利用して自己責任でカーネルパッチを当ててください。

プロファイルの取得

プロファイルの取得方法は大きく分けて2つあります。

1. runtime/pprof が提供しているAPIを使ってファイルに出力する
2. net/http/pprof を使ってプロファイル取得用の http サーバーを立てる

基本的には、短時間で実行が終了するプログラムは1番を、常駐型のプログラムは2番を選ぶと良いです。

runtime/pprof を使う場合

Dave Cheney 氏が runtime/pprof を使いやすくするラッパーライブラリ profile を提供しているので、その使い方を紹介しておきます。

• Dave Cheney 氏による紹介記事 (2013-07-07)
• 更新情報の記事 (2014-10-22)

まずはインストールします。

go get -u github.com/davecheney/profile

次に README にあるやり方で CPU プロファイルを取得してみます。

// sample1.go
// davecheney/profile の利用例
package main

import (
    "github.com/davecheney/profile"
)

func fib(n int) int {
    if n < 2 {
        return n
    }
    return fib(n-1) + fib(n-2)
}

func main() {
    defer profile.Start(profile.CPUProfile).Stop()

    for i := 0; i < 1000; i++ {
        fib(27)
        fib(28)
        fib(29)
        fib(30)
    }
}

このプログラムを実行してみます。

$ go build sample1.go 
$ ./sample1 
2015/12/14 02:43:01 profile: cpu profiling enabled, /tmp/profile012357424/cpu.pprof
$

この利用方法では、 main 関数を抜けるときにプロファイルを止めて、 tmp ディレクトリ内にサブディレクトリを作り cpu.pprof というファイル名でプロファイル結果を保存します。 Ctrl-C でプログラムを止める場合などは、シグナルを処理して main 関数を正常に抜けるように注意してください。

このプロファイル結果に対して pprof のインタラクティブシェルを立ち上げるには、次のようにします。

$ go tool pprof sample1 /tmp/profile012357424/cpu.pprof 
Entering interactive mode (type "help" for commands)
(pprof) 

net/http/pprof を使う場合

先ほどのプログラムを net/http/pprof 版にしてみます。 net/http/pprof は長時間動くプログラム向けなので、 main 関数の中身を無限ループに書き換えています。

// sample2.go
// net/http/pprof の利用例
package main

import (
    "fmt"
    "net"
    "net/http"
    _ "net/http/pprof"
)

func fib(n int) int {
    if n < 2 {
        return n
    }
    return fib(n-1) + fib(n-2)
}

func main() {
    l, err := net.Listen("tcp", ":0")
    if err != nil {
        panic(err)
    }
    fmt.Printf("Listening on %s\n", l.Addr())
    go http.Serve(l, nil)

    for {
        fib(27)
        fib(28)
        fib(29)
        fib(30)
    }
}

net/http/pprof は import の副作用として http.DefaultServeMux に /debug/pprof/* なパスを登録するのでそれを利用します。パッケージが公開している要素を利用していないので、 _ を使わないとコンパイルエラーになります。
":0" を Listen しているのはイディオムで、空きポートを Listen します。実際にはポート番号が割り当てられているので、それを知るために fmt.Printf をしています。

実行するとこのように表示されます。

$ go build sample2.go 
~/t/pprof
$ ./sample2 
Listening on [::]:35664

ターミナルの別のタブを開いて、次のようなコマンドを実行すると30秒間プロファイルを取った後に pprof のインタラクティブシェルが起動します。

$ go tool pprof http://127.0.0.1:35664/debug/pprof/profile
Fetching profile from http://127.0.0.1:35664/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/inada-n/pprof/pprof.127.0.0.1:35664.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) 

http 経由で取得したプロファイルを $HOME/pprof/ 配下に保存しているので、後で起動したいときはそのファイルを指定して起動します。

$ go tool pprof /home/inada-n/pprof/pprof.127.0.0.1:35664.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof)

runtime/pprof を使った場合に比べて、以下の違いに注目してください。

1. go tool pprof コマンドで実行ファイルを省略できる。
2. プロファイル結果が保存されるファイルに .pb.gz という拡張子が付いている。

http 経由のプロファイル取得は、ネットワーク経由で別のサーバーのプログラムのプロファイルを取る際に手元にプロファイル対象となるバイナリが無いケースに対応できるように、生のプロファイル結果に加えてシンボル情報も取得し、プロファイル結果から関数名がわかるようになっています。

とはいえ、 pprof ツールの機能の中にはシンボル情報だけでなくデバッグ情報が必要なものもあるので、できればバイナリファイルを省略せずに指定したほうが良いでしょう。その場合は次のように、URLやプロファイル結果ファイル名の前にバイナリファイル名を書きます。

$ go tool pprof sample2 /home/inada-n/pprof/pprof.127.0.0.1:35664.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof)

pprof コマンドラインツールの使い方

top

一番基本的なコマンドは top です。これは実行時間の多い順に関数を表示します。

(pprof) top
30s of 30.02s total (99.93%)
Dropped 13 nodes (cum <= 0.15s)
      flat  flat%   sum%        cum   cum%
       30s 99.93% 99.93%        30s 99.93%  main.fib
         0     0% 99.93%        30s 99.93%  main.main
         0     0% 99.93%        30s 99.93%  runtime.goexit
         0     0% 99.93%        30s 99.93%  runtime.main

top コマンドに続けて数値を書くと、上位何件を表示するかを指定することができます。

(pprof) top 2
30s of 30.02s total (99.93%)
Dropped 13 nodes (cum <= 0.15s)
Showing top 2 nodes out of 4 (cum >= 30s)
      flat  flat%   sum%        cum   cum%
       30s 99.93% 99.93%        30s 99.93%  main.fib
         0     0% 99.93%        30s 99.93%  main.main

top と 2 の間のスペースは必須ではないので、 top2 のように書くこともできます。

今回のケースでは自明ですが、重い関数自体ではなく、その関数の呼び出し元がどこかが問題になるケースがあります。例えば正規表現が重い事がわかっても、プログラム中に正規表現を使っている箇所が複数あり、どの場所で使ってる正規表現が重いのかがわからない場合などです。こういった場合は、 cumulative (その関数自体だけでなく、その関数から呼びだされた関数の実行時間も合わせた合計時間) でソートする -cum オプションを使います。

(pprof) top -cum
30s of 30.02s total (99.93%)
Dropped 13 nodes (cum <= 0.15s)
      flat  flat%   sum%        cum   cum%
       30s 99.93% 99.93%        30s 99.93%  main.fib
         0     0% 99.93%        30s 99.93%  main.main
         0     0% 99.93%        30s 99.93%  runtime.goexit
         0     0% 99.93%        30s 99.93%  runtime.main
(pprof) 

今回のケースでは、 fib と main が同じサンプル数 (重さ) だったために、 -cum を使っていても fib の方が上に来てしまいました。実際のプログラムでも、サンプル数が足りないとか偏りが激しい場合はこのような事が起こり得ます。

peek

呼び出し元を知る他の方法として、 peek コマンドがあります。このコマンドは引数に関数名のパターンを受け取ります。例えば main. とすれば main パッケージの関数をすべて指定することができます。

(pprof) peek main.
30s of 30.02s total (99.93%)
Dropped 13 nodes (cum <= 0.15s)
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context          
----------------------------------------------------------+-------------
                                               30s   100% |   main.main
       30s 99.93% 99.93%        30s 99.93%                | main.fib
----------------------------------------------------------+-------------
                                               30s   100% |   runtime.main
         0     0% 99.93%        30s 99.93%                | main.main
                                               30s   100% |   main.fib
----------------------------------------------------------+-------------

context カラムが、注目している関数と、その呼び出し元、呼び出し先です。最初の行は main.fib の呼び出し元が main.main だけで、呼び出し先が存在していないことを示しています。次の行は main.main の呼び出し元が runtime.main, 呼び出し先が main.fib のそれぞれ1つずつであることを示しています。今回のサンプルプログラムはシンプルすぎるので意味がありませんが、実際のプログラムではどこからの呼び出しが多いのかなどを知ることができます。

list

もうひとつよく利用するコマンドが list です。このコマンドは引数に関数名のパターンを取ります。

(pprof) list main.
Total: 30.02s
ROUTINE ======================== main.fib in /home/inada-n/t/pprof/sample2.go
       30s     41.66s (flat, cum)   100% of Total
         .          .      7:   "net"
         .          .      8:   "net/http"
         .          .      9:   _ "net/http/pprof"
         .          .     10:)
         .          .     11:
     8.44s      8.44s     12:func fib(n int) int {
     1.19s      1.19s     13:   if n < 2 {
     2.03s      2.03s     14:       return n
         .          .     15:   }
    18.34s        30s     16:   return fib(n-1) + fib(n-2)
         .          .     17:}
         .          .     18:
         .          .     19:func main() {
         .          .     20:   l, err := net.Listen("tcp", ":0")
         .          .     21:   if err != nil {
ROUTINE ======================== main.main in /home/inada-n/t/pprof/sample2.go
         0        30s (flat, cum) 99.93% of Total
         .          .     23:   }
         .          .     24:   fmt.Printf("Listening on %s\n", l.Addr())
         .          .     25:   go http.Serve(l, nil)
         .          .     26:
         .          .     27:   for {
         .      3.17s     28:       fib(27)
         .      5.11s     29:       fib(28)
         .      8.32s     30:       fib(29)
         .     13.40s     31:       fib(30)
         .          .     32:   }
         .          .     33:}
(pprof) 

このように、ソースコードの各行が何秒使ったかをわかりやすく表示してくれます。時間が (flat, cum) で2つ並んでいますが、左側がその関数自体が消費した時間、右側がその行で呼びだしている関数の時間も合わせた消費時間になります。 main.main を見れば、 fib(27), fib(28), fib(29), fib(30) の実行時間が 3, 5, 8, 13 秒とフィボナッチ数列になってるのが判ります。

list コマンドはとても便利ですが、プロファイル結果からソースコードの行を特定するためにデバッグ情報が必要なので、 http 経由でプロファイルするときもバイナリファイルを指定する必要があります。また、ソースを表示するためにデバッグ情報として入っているフルパスを参照しているので、ビルドしたマシンで利用するのが一番楽です。
Mac で Linux 用バイナリをクロスコンパイルして Linux 上で実行している場合は、 Mac から Linux 上の http に対して go tool pprof を実行するか、 Linux 上で一旦プロファイル結果をファイルに書き出して Mac に転送するのが良いでしょう。

また、 list の仲間として disasm という逆アセンブル結果を表示するコマンドもあり、これはバイナリがあればソースコードは必要ありません。

グラフ表示

この png ファイルは次のコマンドで生成しました。

$ go tool pprof -png sample2 ~/pprof/pprof.127.0.0.1\:35664.samples.cpu.001.pb.gz > sample2.png

png の代わりに -svg オプションで svg を使うこともできます。 go-nuts などでプロファイル結果を共有するのによく svg が添付されています。大きいプログラムのプロファイル結果をグラフ化するときは、 -focus=パターン オプションで注目する関数を中央に持ってくると良いでしょう。

次回予告

明日は pprof シリーズ第二弾ということで、 Go が標準で提供している CPU プロファイル以外のプロファイル機能について紹介していきます。