Go pprof 応用編 (CPU 以外のプロファイル)
この記事は KLab Advent Calendar 2015 の18日目の記事です。
Go 言語のランタイムは CPU プロファイル以外にも幾つかのプロファイルを標準で実装していますが、あまり Web 上に実用的な情報がありません。
そこでこの記事では、実際に Go で長期間稼働するサーバーを開発する上で役に立った CPU 以外のプロファイル機能を紹介することにします。
スタックダンプ
/debug/pprof/goroutine で、現時点での全 goroutine のダンプを取得できます。
これは go tool pprof でも利用できますが、実際に使うときはそれよりも curl や wget などを使って /debug/pprof/goroutine?debug=1 をプレインテキスト形式で保存します。
例えば、次のプログラムのスタックダンプを取得してみます。
package main
import (
"net/http"
_ "net/http/pprof"
"time"
)
func NewCounter() <-chan int {
c := make(chan int, 1)
go func() {
for i := 1; ; i++ {
c <- i
}
}()
return c
}
func worker() {
counter := NewCounter()
for c := range counter {
if c == 47 {
return
}
}
}
func main() {
go http.ListenAndServe(":6000", nil)
for {
go worker()
time.Sleep(time.Millisecond * 20)
}
}スタックダンプは次のようになります。
goroutine profile: total 221
1 @ 0x5af768 0x5af543 0x5aae84 0x4958fe 0x495b10 0x4739ca 0x47522d 0x475c9e 0x47348e 0x45d981
# 0x5af768 runtime/pprof.writeRuntimeProfile+0xb8 /usr/local/go/src/runtime/pprof/pprof.go:545
# 0x5af543 runtime/pprof.writeGoroutine+0x93 /usr/local/go/src/runtime/pprof/pprof.go:507
# 0x5aae84 runtime/pprof.(*Profile).WriteTo+0xd4 /usr/local/go/src/runtime/pprof/pprof.go:236
# 0x4958fe net/http/pprof.handler.ServeHTTP+0x37e /usr/local/go/src/net/http/pprof/pprof.go:199
# 0x495b10 net/http/pprof.Index+0x200 /usr/local/go/src/net/http/pprof/pprof.go:211
# 0x4739ca net/http.HandlerFunc.ServeHTTP+0x3a /usr/local/go/src/net/http/server.go:1422
# 0x47522d net/http.(*ServeMux).ServeHTTP+0x17d /usr/local/go/src/net/http/server.go:1699
# 0x475c9e net/http.serverHandler.ServeHTTP+0x19e /usr/local/go/src/net/http/server.go:1862
# 0x47348e net/http.(*conn).serve+0xbee /usr/local/go/src/net/http/server.go:1361
1 @ 0x42d2b3 0x42d374 0x447a19 0x401151 0x42ced0 0x45d981
# 0x447a19 time.Sleep+0xf9 /usr/local/go/src/runtime/time.go:59
# 0x401151 main.main+0x71 /home/inada-n/work/techblog/20151218_inada-n/stack-sample.go:33
# 0x42ced0 runtime.main+0x2b0 /usr/local/go/src/runtime/proc.go:111
...最初の行で、全部で 221 の goroutine が動いていることが判ります。この中には go のランタイムが利用している goroutine も含まれています。
次の行は、スタックトレースと、そのスタックトレースを持つ goroutine の数を示しています。 @ マーク以降がスタックトレースで、 @ マークの手前はそのスタックトレースを持つ goroutine の数になります。
Go のプログラムは数十万の goroutine を利用することがありますが、このように同じスタックトレースをまとめてカウントすることで人間の扱えるサイズのテキストファイルになります。
以降の # で始まる行は、スタックトレースの各アドレスが示す関数と、どのソースコードの何行目だったかをデバッグ情報を元に示しています。
さて、このスタックダンプの続きを見て行きましょう。省略すると実際にはとてつも無く大きいファイルなのかもしれないという印象を持たれるかもしれないので、あえて全部のせています。
1 @ 0x45d981
1 @ 0x42d2b3 0x42d374 0x42d0b8 0x45d981
# 0x42d2b3 runtime.gopark+0x163 /usr/local/go/src/runtime/proc.go:186
# 0x42d374 runtime.goparkunlock+0x54 /usr/local/go/src/runtime/proc.go:191
# 0x42d0b8 runtime.forcegchelper+0xb8 /usr/local/go/src/runtime/proc.go:152
1 @ 0x42d2b3 0x42d374 0x41cf91 0x45d981
# 0x42d2b3 runtime.gopark+0x163 /usr/local/go/src/runtime/proc.go:186
# 0x42d374 runtime.goparkunlock+0x54 /usr/local/go/src/runtime/proc.go:191
# 0x41cf91 runtime.bgsweep+0xb1 /usr/local/go/src/runtime/mgcsweep.go:51
1 @ 0x42d2b3 0x42d374 0x414cda 0x45d981
# 0x42d2b3 runtime.gopark+0x163 /usr/local/go/src/runtime/proc.go:186
# 0x42d374 runtime.goparkunlock+0x54 /usr/local/go/src/runtime/proc.go:191
# 0x414cda runtime.runfinq+0xaa /usr/local/go/src/runtime/mfinal.go:154
213 @ 0x42d2b3 0x42d374 0x403570 0x402ca3 0x4011a8 0x45d981
# 0x4011a8 main.NewCounter.func1+0x48 /home/inada-n/work/techblog/20151218_inada-n/stack-sample.go:13
1 @ 0x42d2b3 0x4273de 0x4268a0 0x4f1b3a 0x4f1ba6 0x4f572c 0x512aad 0x476b71 0x475f73 0x475e36 0x4764cf 0x45d981
# 0x4268a0 net.runtime_pollWait+0x60 /usr/local/go/src/runtime/netpoll.go:157
# 0x4f1b3a net.(*pollDesc).Wait+0x3a /usr/local/go/src/net/fd_poll_runtime.go:73
# 0x4f1ba6 net.(*pollDesc).WaitRead+0x36 /usr/local/go/src/net/fd_poll_runtime.go:78
# 0x4f572c net.(*netFD).accept+0x27c /usr/local/go/src/net/fd_unix.go:408
# 0x512aad net.(*TCPListener).AcceptTCP+0x4d /usr/local/go/src/net/tcpsock_posix.go:254
# 0x476b71 net/http.tcpKeepAliveListener.Accept+0x41 /usr/local/go/src/net/http/server.go:2135
# 0x475f73 net/http.(*Server).Serve+0xb3 /usr/local/go/src/net/http/server.go:1887
# 0x475e36 net/http.(*Server).ListenAndServe+0x136 /usr/local/go/src/net/http/server.go:1877
# 0x4764cf net/http.ListenAndServe+0x8f /usr/local/go/src/net/http/server.go:1967
1 @ 0x40df9e 0x44807e 0x45d981
# 0x40df9e runtime.notetsleepg+0x4e /usr/local/go/src/runtime/lock_futex.go:203
# 0x44807e runtime.timerproc+0xde /usr/local/go/src/runtime/time.go:209これを眺めて見ると、明らかにカウントが大きいスタックトレースがありますね。
213 @ 0x42d2b3 0x42d374 0x403570 0x402ca3 0x4011a8 0x45d981
# 0x4011a8 main.NewCounter.func1+0x48 /home/inada-n/work/techblog/20151218_inada-n/stack-sample.go:13この部分のソースコードを見てみましょう。
func NewCounter() <-chan int {
c := make(chan int, 1)
go func() {
for i := 1; ; i++ {
c <- i // ここ！
}
}()
return c
}これで、 Go での並列プログラミング初心者がやりがちな goroutine リークが発見できました。
Note: Go の GC は他の大抵のプログラミング言語と同様に、スタックとグローバル変数をルートとして参照されているオブジェクト以外を回収します。
channel も close されているかどうかにかかわらず、その条件を満たしていれば回収されます。逆にいえば、そのチャンネルを参照している goroutine が生き残っていれば、たとえその goroutine が送信待ちしていて受信者がいない状況であっても回収されず、その送信待ち goroutine はリークしてしまいます。
このように goroutine リークを見つける以外にも、アプリケーションのレイテンシが落ちている状態でスタックダンプを取れば何を待っている goroutine が多いのかを判別するためにスタックダンプを利用することができます。
実際にスタックダンプを活用するには、問題が起こってからではなく開発中から時々スタックダンプを観察し、ライブラリがどのように goroutine を利用しているのか、平常時はどの goroutine がどれだけあるのかなどを把握しておくとよいでしょう。
なお、 /debug/pprof/goroutine?debug=2 とすることで、同じスタックトレースをまとめない完全なスタックダンプを取得することができます。
こちらには各 goroutine がどこで起動されたかや、各関数の引数の値 (ただし文字列や構造体はポインタになるので中身までは見えない) が表示されるので、より精密なデバッグに利用できます。
メモリープロファイル (ヒーププロファイル)
メモリープロファイルは前回のGC実行時点での、Goのアロケータが取得したプロファイルを取得します。こちらは普通に go tool pprof http://localhost:6000/debug/pprof/heap で取得します。
メモリープロファイルには、 inuse_space （デフォルト), inuse_objects, alloc_space, alloc_objects の4種類の情報があります。
名前の前半部分で、 inuse は前回のGC実行で回収されなかった、使用中のメモリーのことを指し、 alloc は生存しているものも回収されたものも含めてすべてのアロケートされたメモリーを指します。
名前の後半部分は、 space はメモリーのサイズを、 objects はオブジェクトの数 (一度にアロケートされるメモリーの塊をオブジェクトと呼びます) を示します。例えば 1MB のメモリを2回確保すれば、 space は 2MB, objects は 2 になります。
どのプロファイルを利用するかは go tool pprof のオプションで指定します。例えば inuse_objects を利用する場合は go tool pprof -inuse_objects URL のようにします。
また、メモリープロファイルを利用するときには、 go tool pprof の -base オプションを覚えておきましょう。 -base 前回のプロファイル を指定することで、2つのプロファイル結果の差分を調査することができます。
4種類のプロファイル x 絶対/差分 で合計8種類の組み合わせがありますが、一般的な調査目的で利用するのはごく一部です。これから実際に使い方を解説していきます。
もう1つ注意点があります。メモリープロファイルはデフォルトで有効になっていますが、パフォーマンスへの影響を抑えるために精度が犠牲になっています。 runtime.MemProfileRate という変数を小さくする (単位はバイト、デフォルト値は 512 * 1024) ことで精度を上げることができますが、この変数を変更する前に取得したデータも変更後の値で計算してしまうので、 main 関数の先頭や main パッケージの init 関数など、なるべくアロケートが発生する前に設定するべきです。
この変数を1に設定すれば、理論上完全にメモリ利用を調査することができるはずです。この変数の値がどう利用されているかなどについては次回の記事で紹介します。
メモリー使用量の調査
一番単純なのは、メモリー使用量を削減したいとか、予想以上にメモリーを消費しているからなぜなのか知りたいなどの理由で、メモリー使用量の内訳を調査するケースです。
この場合はデフォルトの inuse_space を絶対値で調査するだけで十分です。CPUプロファイルを調査するときと同じようにすれば、使用中のメモリーを大量に確保しているのがどこかを突き止めることができます。
サンプルコード:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"time"
)
func genMap() map[string]string {
m := make(map[string]string)
for i := 0; i < 1000000; i++ {
m[fmt.Sprintf("key%d", i)] = fmt.Sprintf("val%d", i)
}
return m
}
func genSlice() []string {
s := []string{}
for i := 0; i < 1000000; i++ {
s = append(s, fmt.Sprintf("key%d", i))
s = append(s, fmt.Sprintf("val%d", i))
}
return s
}
func main() {
runtime.MemProfileRate = 1024
go http.ListenAndServe(":6000", nil)
m := genMap()
s := genSlice()
for i := 0; i < 10000; i++ {
time.Sleep(time.Second)
}
fmt.Println(m, s) // GCがsleep中にmを消さないためのおまじない。ここに来る前に C-c で止める
}go tool pprof の実行例:
$ go tool pprof mem-sample http://[::1]:6000/debug/pprof/heap
Fetching profile from http://[::1]:6000/debug/pprof/heap
Saved profile in /home/inada-n/pprof/pprof.mem-sample.[::1]:6000.inuse_objects.inuse_space.005.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
123.11MB of 123.12MB total ( 100%)
Dropped 60 nodes (cum <= 0.62MB)
flat flat% sum% cum cum%
69.24MB 56.24% 56.24% 99.36MB 80.70% main.genMap
40.89MB 33.21% 89.45% 40.89MB 33.21% fmt.Sprintf
12.98MB 10.54% 100% 23.75MB 19.29% main.genSlice
0 0% 100% 123.11MB 100% main.main
0 0% 100% 123.12MB 100% runtime.goexit
0 0% 100% 123.12MB 100% runtime.main
(pprof) top -cum
123.11MB of 123.12MB total ( 100%)
Dropped 60 nodes (cum <= 0.62MB)
flat flat% sum% cum cum%
0 0% 0% 123.12MB 100% runtime.goexit
0 0% 0% 123.12MB 100% runtime.main
0 0% 0% 123.11MB 100% main.main
69.24MB 56.24% 56.24% 99.36MB 80.70% main.genMap
40.89MB 33.21% 89.45% 40.89MB 33.21% fmt.Sprintf
12.98MB 10.54% 100% 23.75MB 19.29% main.genSlice
(pprof) list main.main
Total: 123.12MB
ROUTINE ======================== main.main in /home/inada-n/work/techblog/20151218_inada-n/mem-sample.go
0 123.11MB (flat, cum) 100% of Total
. . 26:}
. . 27:
. . 28:func main() {
. . 29: runtime.MemProfileRate = 1024
. . 30: go http.ListenAndServe(":6000", nil)
. 99.36MB 31: m := genMap()
. 23.75MB 32: s := genSlice()
. . 33: for i := 0; i < 10000; i++ {
. . 34: time.Sleep(time.Second)
. . 35: }
. . 36: fmt.Println(m, s)
. . 37:}メモリーリークの調査
メモリープロファイラを使うもうひとつのよくある目的は、メモリーリークの調査です。すでにメモリーリークしているプログラムでどこがメモリーリークしているのかを調査したり、本番投入前のプログラムにメモリーリークがないことを確認したい事が多いでしょう。
この場合、時間差で2回プロファイルを取得して、 inuse の差分を調査することでメモリー使用量が増えている箇所を発見することができます。
単にメモリーリークの量を減らしたいのであれば inuse_space で良いですが、メモリーリークを根絶したいのであれば runtime.MemProfileRate をできるだけ小さくして inuse_space と inuse_objects の両方を観察することで小さいメモリオブジェクトのリークも見逃さないようにできます。
サンプルコード:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"time"
)
func leaker(c chan bool) []string {
s := []string{}
for i := 0; ; i++ {
select {
case <-c:
default:
}
s = append(s, fmt.Sprintf("foo%d", i))
if len(s)%1000 == 0 {
fmt.Println(len(s))
}
time.Sleep(time.Millisecond)
}
return s
}
func main() {
runtime.MemProfileRate = 1
go http.ListenAndServe(":6000", nil)
c := make(chan bool)
go leaker(c)
for {
time.Sleep(time.Second)
}
}go tool pprof の実行例:
$ go tool pprof mem-sample2 http://localhost:6000/debug/pprof/heap
Fetching profile from http://localhost:6000/debug/pprof/heap
Saved profile in /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof)
$ go tool pprof -base /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.001.pb.gz mem-sample2 http://localhost:6000/debug/pprof/heap
Fetching profile from http://localhost:6000/debug/pprof/heap
Saved profile in /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.003.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
3.70MB of 3.44MB total ( 100%)
Dropped 118 nodes (cum <= 0.02MB)
flat flat% sum% cum cum%
1.96MB 56.95% 56.95% 3.44MB 100% main.leaker
1.75MB 50.81% 100% 1.75MB 50.83% fmt.Sprintf
0 0% 100% 3.43MB 99.89% runtime.goexit
(pprof) list main.leaker
Total: 3.44MB
ROUTINE ======================== main.leaker in /home/inada-n/work/techblog/20151218_inada-n/mem-sample2.go
1.96MB 3.44MB (flat, cum) 100% of Total
. . 14: select {
. . 15: case <-c:
. . 16: default:
. . 17: }
. . 18:
1.96MB 3.70MB 19: s = append(s, fmt.Sprintf("foo%d", i))
. . 20: if len(s)%1000 == 0 {
-48B -48B 21: fmt.Println(len(s))
. . 22: }
. -271.19kB 23: time.Sleep(time.Millisecond)
. . 24: }
. . 25: return s
. . 26:}
. . 27:
. . 28:func main() {
(pprof)
$ go tool pprof -inuse_objects -base /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.001.pb.gz mem-sample2 http://localhost:6000/debug/pprof/heap
Fetching profile from http://localhost:6000/debug/pprof/heap
http fetch http://localhost:6000/debug/pprof/heap: Get http://localhost:6000/debug/pprof/heap: dial tcp 127.0.0.1:6000: getsockopt: connection refused
~/work/techblog/20151218_inada-n (pprof2)
$ go tool pprof -inuse_objects -base /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.001.pb.gz mem-sample2 /home/inada-n/pprof/pprof.mem-sample2.localhost:6000.inuse_objects.inuse_space.003.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
110088 of 105725 total ( 100%)
Dropped 118 nodes (cum <= 528)
flat flat% sum% cum cum%
114445 100% 100% 114448 100% fmt.Sprintf
0 0% 100% 105716 100% runtime.goexit
-4357 -4.1% 100% 105752 100% main.leaker
(pprof) list main.leaker
Total: 105725
ROUTINE ======================== main.leaker in /home/inada-n/work/techblog/20151218_inada-n/mem-sample2.go
-4357 105752 (flat, cum) 100% of Total
. . 14: select {
. . 15: case <-c:
. . 16: default:
. . 17: }
. . 18:
-4354 110094 19: s = append(s, fmt.Sprintf("foo%d", i))
. . 20: if len(s)%1000 == 0 {
-3 -3 21: fmt.Println(len(s))
. . 22: }
. -4339 23: time.Sleep(time.Millisecond)
. . 24: }
. . 25: return s
. . 26:}
. . 27:
. . 28:func main() {
(pprof)fmt.Sprintf は明確に捕捉できていますが、それ以外のリークしていないはずの部分にも差分があったり、逆にスライスへの append がマイナスになっていたりします。
これはGCが実行されるタイミングの問題かなにかだと諦めていますが、対策として2回だけでなく何度かプロファイルを取得して傾向を見ることにしています。
GCのチューニング
Go の GC は、 Go 1.5 の段階では世代なしの並列な Mark & Sweep で、型を利用してポインタを正確に把握しています。
なのでGCの実行時間が長い時にチューニングするには、 scan が遅いのであればプログラム中の生存しているポインタの数を減らす、アロケートが多くて頻繁にGCが発生しているならアロケートを減らすチューニングが有効です。
(GCのどの部分が遅いのかは GODEBUG 環境変数に gctrace=1 を設定して出力を見ます)
scan を減らす場合は、通常のメモリ使用量の調査を行い、メモリを大量に使っているところからポインタをたくさん持っている箇所を探します。
アロケートを減らす場合は、 alloc_objects を見てアロケートが多い箇所を探すことができます。
紹介しなかったプロファイル
Go のランタイムが提供している他のプロファイルについて簡単に触れておきます。
1つ目は ThreadCreateProfile で、これは goroutine を動かすのに利用しているOSレベルのスレッドを生成することになった箇所のプロファイルです。
Go は通常CPUコア数や設定された数の goroutine を並列に動かそうとOSスレッドを用意しますが、CGOの呼び出しやシステムコールがすぐに戻ってこなかった場合にはさらにOSスレッドを立ち上げます。
ThreadCreateProfile を利用することで、プログラムの中でシステムコールがブロックしている部分を見つけることができるかもしれません。
プログラムが大量のOSスレッドを利用しているけれども、大量のスレッドが必要になるのが一瞬なので普通にスタックダンプをとってもその瞬間が捉えられない場合などに使うと良いでしょう。
もう1つが BlockProfile です。これは Mutex 待ちや channel 待ちなどでブロックする時間をプロファイルできます。
プログラムのレイテンシが時々異常に悪化するけれども、CPU使用率が高いわけではなく、またその瞬間のスタックダンプを取得することも難しいという場合に利用すると良いかもしれません。
しかし、 BlockProfile のプロファイリングはデフォルトで無効になっているので、事前に runtime.SetBlockProfile を設定しておく必要があります。
次回予告
明日は、 pprof の仕組みと、独自のプロファイルの作り方を解説します。
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。
広報X
広報Facebookおすすめ
合わせて読みたい
このブログについて
KLabのゲーム開発・運用で培われた技術や挑戦とそのノウハウを発信します。