Go pprof 入門編 (CPU Profile とコマンドラインツール)
このエントリーは、 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つあります。
runtime/pprofが提供しているAPIを使ってファイルに出力するnet/http/pprofを使ってプロファイル取得用の http サーバーを立てる
基本的には、短時間で実行が終了するプログラムは1番を、常駐型のプログラムは2番を選ぶと良いです。
runtime/pprof を使う場合
Dave Cheney 氏が runtime/pprof を使いやすくするラッパーライブラリ profile を提供しているので、その使い方を紹介しておきます。
まずはインストールします。
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 を使った場合に比べて、以下の違いに注目してください。
go tool pprofコマンドで実行ファイルを省略できる。- プロファイル結果が保存されるファイルに
.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.maintop コマンドに続けて数値を書くと、上位何件を表示するかを指定することができます。
(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.maintop と 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.pngpng の代わりに -svg オプションで svg を使うこともできます。 go-nuts などでプロファイル結果を共有するのによく svg が添付されています。大きいプログラムのプロファイル結果をグラフ化するときは、 -focus=パターン オプションで注目する関数を中央に持ってくると良いでしょう。
次回予告
明日は pprof シリーズ第二弾ということで、 Go が標準で提供している CPU プロファイル以外のプロファイル機能について紹介していきます。
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。
広報X
広報Facebook記事検索
おすすめ
合わせて読みたい
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。