net/http/pprof のheapの値は何を表しているのか

pprofのWeb UIの "heap" の数って何を表すんだろう？ pic.twitter.com/JWlAgIL5Ka
— k1LoW (@k1LoW) 2018年9月7日

tcprxyというTCPプロキシを作っています。

8月中旬くらいから「よし、プロダクションレディになるくらいまで開発してやろう」と、時間を見つけては設定ファイルを読めるようにしたり、server_starterと連携できるようにしたり、取得できる情報の充実を図ったりしていました。いろいろ機能を追加してみたのですがそれはまたの機会に。

そして、「あとは、常時起動していてメモリリークが発生しないことを確認すればよいだろう」と、とりあえず見よう見まねで net/http/pprof を使ってブラウザ上からプロファイルを確認してみました。

具体的には main.go を以下のように修正して、tcprxy経由でMySQLに対してmysqlslapを使ってクエリを投げていました。mysqlslap <-> tcprxy <-> MySQL という感じです。

diff --git a/main.go b/main.go
index 56f4e32..5689432 100644
--- a/main.go
+++ b/main.go
@@ -20,8 +20,16 @@

 package main

-import "github.com/k1LoW/tcprxy/cmd"
+import (
+       "net/http"
+       _ "net/http/pprof"
+
+       "github.com/k1LoW/tcprxy/cmd"
+)

 func main() {
+       go func() {
+               http.ListenAndServe("localhost:6060", nil)
+       }()
        cmd.Execute()
 }

ところが、 http://localhost:6060/debug/pprof/ に表示されている値を眺めていると、

あれ、heapの値が増え続ける

goroutineの値はMySQLへの通信がなくなると元の値に戻るのに、heapの値だけが増え続けています。

自分がわからないところでメモリリークが起こっているの？

計測してみる

と思ったのでとりあえず計測してみました。

go version

> go version
go version go1.10.2 darwin/amd64

計測コード

for i in {1..1000} ; do
    echo "Do ${i}"
    mysqlslap \
  --no-defaults \
  --concurrency=50 \
  --iterations=10 \
  --engine=innodb \
  --auto-generate-sql \
  --auto-generate-sql-add-autoincrement \
  --auto-generate-sql-load-type=mixed \
  --auto-generate-sql-write-number=100 \
  --number-of-queries=1000 \
  --host=127.0.0.1 \
  --port=3306 \
  --user=root \
  --password=mypass \
  --ssl-mode=DISABLED >> heap.dump
    sleep 2
    curl -s http://localhost:6060/debug/pprof/ >> heap.dump
    curl -s http://localhost:6060/debug/pprof/heap?debug=1 >> heap.dump
done

tcprxy越しにmysqlslapで連続して通信をします。sleepを挟むことでTCPプロキシにおける接続数を一旦0にして、そのときのheapの情報を都度記録していきます。

実行時間としては一晩くらいかかりました。

計測結果

"pprof heap count (http://localhost:6060/debug/pprof/ に表示されているheapの値)" は明らかに増え続けています。

しかし"HeapSys"や"HeapAlloc"などその他の値にはその傾向はありません。

ソースコードを読んでみる

net/http/pprof からソースを追ってみました。

まず、src/runtime/pprof/pprof.go の countHeap() が http://localhost:6060/debug/pprof/ に表示されているheapの値のようです。

// countHeap returns the number of records in the heap profile.
func countHeap() int {
  n, _ := runtime.MemProfile(nil, true)
  return n
}

上記コードのように、runtime.MemProfile() の返り値を表示しているみたいです。

runtime.Memprofile

https://golang.org/pkg/runtime/#MemProfile

runtime.MemProfileのgodocを読むと

MemProfile returns a profile of memory allocated and freed per allocation site.

allocated and freed ということは開放された割り当てメモリも返すようです。

MemProfile returns n, the number of records in the current memory profile. If len(p) >= n, MemProfile copies the profile into p and returns n, true. If len(p) < n, MemProfile does not change p and returns n, false.

countHeap()ではruntime.MemProfileの第1引数の []MemProfileRecord は nil なので、常にそのときの割り当てプロファイルの数を返すようです。

countHeap()ではruntime.MemProfileの第2引数の inuseZero は true なので

If inuseZero is true, the profile includes allocation records where r.AllocBytes > 0 but r.AllocBytes == r.FreeBytes. These are sites where memory was allocated, but it has all been released back to the runtime.

ということで、割り当てプロファイルの数にはランタイムにリリースされた分も含むようです。

mbuckets

runtime.MemProfile のコードを追うと mbuckets の数をカウントしています。

mbuckets は *runtime.bucket というコールスタックごとのプロファイリング情報の構造体で mbucktes はメモリ用のプロファイリング情報をもっている形になります。

以下は src/runtime/mprof.go からの抜粋

type bucket struct {
  next    *bucket
  allnext *bucket
  typ     bucketType // memBucket or blockBucket (includes mutexProfile)
  hash    uintptr
  size    uintptr
  nstk    uintptr
}

個人的に面白かったのが、プロファイリング情報群をsliceか配列かで持っているのかな？と思っていたら、そうではなくて next に次の bucket をポインタで保持しているということです。

そういうものなんですね。The representation is a bit sleazy, inherited from C. とコメントに書いてありました。

mbuckets はsrc/runtime/mprof.goの mProf_Malloc() -> stkbucket() で必要に応じて追加されるみたいです。

mbuckets を減らす処理は見つけられませんでした。

なぜ、計測回数を増やすごとにプロファイルの情報の数が増えるのか？

結論から言うとまだわかっていません。

src/runtime/mprof.go の stkbucket() のコードを読むと、bucketを保持するハッシュテーブルのサイズには上限(buckHashSize)があるようです。

そして、必要に応じて（同じプロファイル情報であれば？）再利用もされています。（以下は、sktbucket()のコードを抜粋）

  i := int(h % buckHashSize)
  for b := buckhash[i]; b != nil; b = b.next {
    if b.typ == typ && b.hash == h && b.size == size && eqslice(b.stk(), stk) {
      return b
    }
  }

  if !alloc {
    return nil
  }

  // Create new bucket.
  b := newBucket(typ, len(stk))

ただ、同じ処理（mysqlsrap）を繰り返しているのに、計測回数を増やすごとにプロファイルの情報が増えるというところがしっくりきていないところです（計測回数対しての線形増加なら「毎回新規でプロファイルを記録するんだな」とわかるのですが）。

計測結果を保存したheap.dumpにその記録されたプロファイル情報の詳細が残っているので、次回、そこから調べてみようと思っています。

まとめ

計測してみた結果、「http://localhost:6060/debug/pprof/ に表示されているheapの値が増える = メモリリークが発生している」ということではないことがわかった。
http://localhost:6060/debug/pprof/ に表示されているheapの値はメモリ割り当てのタイミングで必要に応じて追加されるプロファイルの情報の数であることがわかった。
- そしてその中にはすでに開放されているものも含まれているということもわかった。
「なぜ、計測回数を増やすごとにプロファイルの情報の数が増えるのか」はわからなかった。

とりあえず、tcprxyにメモリリークがなさそうであることはわかったので良かったです。