概要
前回
にてpprofのコマンドラインツールの使い方を説明しました。
今回はメモリについて
といったところの調査方法を説明します。
環境
- golang 1.11.1
ケース１：このバッチ処理、メモリすごく喰ってない？
一定時間で処理が終わるバッチ処理はruntime/pprofを使います。
もちろん実行途中でプロファイリングしたい場合はnet/http/pprofでも構いません。
ケースバイケースで使用してください。
runtime/pprofを使いやすい形にラップしている以下のライブラリを使います。
サンプルコード
今回はメモリのプロファイルを取りたいので
defer profile.Start(profile.MemProfile).Stop()
を設定します。
import ( "fmt" "strconv" "github.com/pkg/profile" ) func main() { defer profile.Start(profile.MemProfile, profile.ProfilePath(".")).Stop() fmt.Println("start") exec() fmt.Println("end") } func exec() { var someMap = make(map[string]string) doNothing("foo", 100000) addMap(someMap, "bar", 10000) addMap(someMap, "buzz", 1000000) } func addMap(s map[string]string, prefix string, count int) { for i := 0; i < count; i++ { key := prefix + "key" + strconv.Itoa(i) val := "value" + strconv.Itoa(i) s[key] = val } } func doNothing(prefix string, count int) { for i := 0; i < count; i++ { key := prefix + "key" + strconv.Itoa(i) val := "value" + strconv.Itoa(i) key = key + val } }
コードを読めば分かりますが、マップに追加している処理が怪しいですね。
プロファイリング
profile.ProfilePath(".")を付けたので、実行するとローカルにmem.pprofファイルが生成されます。
では解析してみましょう
$ go tool pprof YOUR_BINARY mem.pprof
top
まずはtopで全体像を把握します。
(pprof) top Showing nodes accounting for 66.12MB, 100% of 66.12MB total flat flat% sum% cum cum% 65.55MB 99.14% 99.14% 66.12MB 100% main.addMap 0.57MB 0.86% 100% 0.57MB 0.86% strconv.formatBits 0 0% 100% 66.12MB 100% main.exec 0 0% 100% 66.12MB 100% main.main 0 0% 100% 66.12MB 100% runtime.main 0 0% 100% 0.57MB 0.86% strconv.FormatInt 0 0% 100% 0.57MB 0.86% strconv.Itoa
想定どおりですがmapにデータを投入するaddMapメソッドでメモリを食っています。
list
次にlistでコードのどこでメモリを食っているか詳細を見ます。
(pprof) list main. Total: 66.12MB ROUTINE ======================== main.addMap in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/main.go 65.55MB 66.12MB (flat, cum) 100% of Total . . 28: addMap(someMap, "buzz", 1000000) . . 29:} . . 30: . . 31:func addMap(s map[string]string, prefix string, count int) { . . 32: for i := 0; i < count; i++ { 12.38MB 12.45MB 33: key := prefix + "key" + strconv.Itoa(i) 12.07MB 12.57MB 34: val := "value" + strconv.Itoa(i) 41.10MB 41.10MB 35: s[key] = val . . 36: } . . 37:} . . 38: . . 39:func doNothing(prefix string, count int) { . . 40: for i := 0; i < count; i++ { ROUTINE ======================== main.exec in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/main.go 0 66.12MB (flat, cum) 100% of Total . . 22: . . 23:func exec() { . . 24: var someMap = make(map[string]string) . . 25: . . 26: doNothing("foo", 100000) . 320.62kB 27: addMap(someMap, "bar", 10000) . 65.81MB 28: addMap(someMap, "buzz", 1000000) . . 29:} . . 30: . . 31:func addMap(s map[string]string, prefix string, count int) { . . 32: for i := 0; i < count; i++ { . . 33: key := prefix + "key" + strconv.Itoa(i) ROUTINE ======================== main.main in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/main.go 0 66.12MB (flat, cum) 100% of Total . . 14: . . 15:func main() { . . 16: defer profile.Start(profile.MemProfile, profile.ProfilePath(".")).Stop() . . 17: . . 18: fmt.Println("start") . 66.12MB 19: exec() . . 20: fmt.Println("end") . . 21:} . . 22: . . 23:func exec() { . . 24: var someMap = make(map[string]string)
上記から
addMap()の中のマップ追加- マップに追加する文字列生成
でメモリを使っていることが分かります。
前者は想定どおりですが、後者はなぜでしょうか？
理由は文字列も実態は[]byteなので、参照が残ればヒープ領域に保存されるためです。
今回だとmapによって参照が残るため、このようにメモリを消費した箇所として指摘されたのでしょう。
一方doNothing()の方は同じ文字列生成の処理ですが、参照が残らないためヒープでなくスタックで処理され、pprofによる指摘はされません。
ヒープ割当になるのかビルドで確認
golangはビルド時に-gcflags '-m'というオプションを付けるとヒープに保存するかどうかをチェックできます。
$ go build -gcflags '-m' main.go # command-line-arguments ./main.go:39:16: doNothing prefix does not escape ./main.go:41:25: doNothing prefix + "key" + strconv.Itoa(i) does not escape ./main.go:42:18: doNothing "value" + strconv.Itoa(i) does not escape ./main.go:43:13: doNothing key + val does not escape ./main.go:33:25: prefix + "key" + strconv.Itoa(i) escapes to heap ./main.go:34:18: "value" + strconv.Itoa(i) escapes to heap ./main.go:31:13: addMap s does not escape ./main.go:31:34: addMap prefix does not escape ./main.go:24:20: exec make(map[string]string) does not escape ./main.go:18:14: "start" escapes to heap ./main.go:20:14: "end" escapes to heap ./main.go:16:21: main ... argument does not escape ./main.go:18:13: main ... argument does not escape ./main.go:20:13: main ... argument does not escape
escapes to heapと表示されればヒープに保存されます。
does not escapeと表示されればヒープには保存されません。
このチェックでもaddMapの文字列はヒープに、doNothingの文字列はスタックに保存される事が分かります。
ケース２：メモリリークしてない？
メモリリークしているかどうかは時間を分けて複数回プロファイルを取ることで分かります。
サンプルコード
import ( "fmt" "log" "net/http" "strconv" _ "net/http/pprof" ) func main() { go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() fmt.Println("start") exec() fmt.Println("end") } func exec() { var someMap = make(map[string]string) addMap(someMap) } func addMap(s map[string]string) { i := int64(0) for { key := "key" + strconv.FormatInt(i, 10) val := "value" + strconv.FormatInt(i, 10) s[key] = val i++ } }
forループで明らかにマップに詰め込みまくるのでリークするのは一目瞭然ですね。
プロファイリング
先程のコードを実行してプロファイルを２回実行します。
今回はメモリを解析するのでhttp://localhost:6060/debug/pprof/heapを指定します。
１回目
$ go tool pprof YOUR_BINARY http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users/jun06t/pprof/pprof.leak.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
このままコマンドラインツールでサクッとtopやlistを出してもいいですし、自動で保存されるのでそれを後から利用しても大丈夫です。
２回目
少し時間を置いてもう一度実行します。
ファイル名は自動で連番されます。
$ go tool pprof YOUR_BINARY http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users/jun06t/pprof/pprof.leak.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
結果
１回目のデータ
addMapで500MB以上使ってます。
(pprof) top Showing nodes accounting for 546.51MB, 100% of 546.51MB total flat flat% sum% cum cum% 538.51MB 98.54% 98.54% 546.51MB 100% main.addMap 8MB 1.46% 100% 8MB 1.46% strconv.formatBits 0 0% 100% 546.51MB 100% main.exec 0 0% 100% 546.51MB 100% main.main 0 0% 100% 546.51MB 100% runtime.main 0 0% 100% 8MB 1.46% strconv.FormatInt (pprof) list main. Total: 546.51MB ROUTINE ======================== main.addMap in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 538.51MB 546.51MB (flat, cum) 100% of Total . . 26:} . . 27: . . 28:func addMap(s map[string]string) { . . 29: i := int64(0) . . 30: for { 41.50MB 48MB 31: key := "key" + strconv.FormatInt(i, 10) 46MB 47.50MB 32: val := "value" + strconv.FormatInt(i, 10) 451MB 451MB 33: s[key] = val . . 34: i++ . . 35: } . . 36:} ROUTINE ======================== main.exec in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 0 546.51MB (flat, cum) 100% of Total . . 20:} . . 21: . . 22:func exec() { . . 23: var someMap = make(map[string]string) . . 24: . 546.51MB 25: addMap(someMap) . . 26:} . . 27: . . 28:func addMap(s map[string]string) { . . 29: i := int64(0) . . 30: for { ROUTINE ======================== main.main in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 0 546.51MB (flat, cum) 100% of Total . . 13: go func() { . . 14: log.Println(http.ListenAndServe("localhost:6060", nil)) . . 15: }() . . 16: . . 17: fmt.Println("start") . 546.51MB 18: exec() . . 19: fmt.Println("end") . . 20:} . . 21: . . 22:func exec() { . . 23: var someMap = make(map[string]string)
２回目のデータ
addMapで1GB以上使ってます。
明らかにリークしてますね。
(pprof) top Showing nodes accounting for 1110.52MB, 100% of 1110.52MB total flat flat% sum% cum cum% 1102.02MB 99.23% 99.23% 1110.52MB 100% main.addMap 8.50MB 0.77% 100% 8.50MB 0.77% strconv.formatBits 0 0% 100% 1110.52MB 100% main.exec 0 0% 100% 1110.52MB 100% main.main 0 0% 100% 1110.52MB 100% runtime.main 0 0% 100% 8.50MB 0.77% strconv.FormatInt (pprof) list main. Total: 1.08GB ROUTINE ======================== main.addMap in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 1.08GB 1.08GB (flat, cum) 100% of Total . . 26:} . . 27: . . 28:func addMap(s map[string]string) { . . 29: i := int64(0) . . 30: for { 98MB 105MB 31: key := "key" + strconv.FormatInt(i, 10) 92.50MB 94MB 32: val := "value" + strconv.FormatInt(i, 10) 911.51MB 911.51MB 33: s[key] = val . . 34: i++ . . 35: } . . 36:} ROUTINE ======================== main.exec in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 0 1.08GB (flat, cum) 100% of Total . . 20:} . . 21: . . 22:func exec() { . . 23: var someMap = make(map[string]string) . . 24: . 1.08GB 25: addMap(someMap) . . 26:} . . 27: . . 28:func addMap(s map[string]string) { . . 29: i := int64(0) . . 30: for { ROUTINE ======================== main.main in /Users/jun06t/.go/src/github.com/jun06t/golang-practice/pprof/memory/leak/main.go 0 1.08GB (flat, cum) 100% of Total . . 13: go func() { . . 14: log.Println(http.ListenAndServe("localhost:6060", nil)) . . 15: }() . . 16: . . 17: fmt.Println("start") . 1.08GB 18: exec() . . 19: fmt.Println("end") . . 20:} . . 21: . . 22:func exec() { . . 23: var someMap = make(map[string]string)
addMapのところでメモリがどんどん増えていくことが分かったので、リーク箇所が特定できました。
まとめ
pprofでのメモリのプロファイリングを説明しました。
Go言語は基本的にスタックで処理するので無駄なメモリ消費はありませんが、オンメモリにガツガツ載せたりループでの考慮が足りなかったりでメモリが枯渇することはあるのでその時はプロファイリングで調査してみてください。
