Carpe Diem

備忘録

Golangのpprofの使い方【メモリ編】

概要

前回

christina04.hatenablog.com

にてpprofのコマンドラインツールの使い方を説明しました。

今回はメモリについて

といったところの調査方法を説明します。

環境

ケース1:このバッチ処理、メモリすごく喰ってない?

一定時間で処理が終わるバッチ処理runtime/pprofを使います。
もちろん実行途中でプロファイリングしたい場合はnet/http/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 memory 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ループで明らかにマップに詰め込みまくるのでリークするのは一目瞭然ですね。

プロファイリング

先程のコードを実行してプロファイルを2回実行します。
今回はメモリを解析するのでhttp://localhost:6060/debug/pprof/heapを指定します。

1回目

$ go tool pprof leak 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

このままコマンドラインツールでサクッとtoplistを出してもいいですし、自動で保存されるのでそれを後から利用しても大丈夫です。

2回目

$ go tool pprof leak 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

結果

1回目のデータ

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)

2回目のデータ

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言語は基本的にスタックで処理するので無駄なメモリ消費はありませんが、オンメモリにガツガツ載せたりループでの考慮が足りなかったりでメモリが枯渇することはあるのでその時はプロファイリングで調査してみてください。

ソース