net/http/pprof のheapの値は何を表しているのか
pprofのWeb UIの "heap" の数って何を表すんだろう？pic.twitter.com/JWlAgIL5Ka
— k1LoW (@k1LoW)2018年9月7日
8月中旬くらいから「よし、プロダクションレディになるくらいまで開発してやろう」と、時間を見つけては設定ファイルを読めるようにしたり、server_starterと連携できるようにしたり、取得できる情報の充実を図ったりしていました。いろいろ機能を追加してみたのですがそれはまたの機会に。
そして、「あとは、常時起動していてメモリリークが発生しないことを確認すればよいだろう」と、とりあえず見よう見まねで net/http/pprof を使ってブラウザ上からプロファイルを確認してみました。
具体的には main.go を以下のように修正して、tcprxy経由でMySQLに対してmysqlslapを使ってクエリを投げていました。mysqlslap <-> tcprxy <-> MySQL という感じです。
diff --git a/main.go b/main.goindex 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 versiongo version go1.10.2 darwin/amd64
計測コード
for iin{1..1000} ;doecho"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.dumpsleep2 curl-s http://localhost:6060/debug/pprof/>> heap.dump curl-s http://localhost:6060/debug/pprof/heap?debug=1>> heap.dumpdone
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 bucketstruct { next *bucket allnext *bucket typ bucketType// memBucket or blockBucket (includes mutexProfile) hashuintptr sizeuintptr nstkuintptr}
個人的に面白かったのが、プロファイリング情報群を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 {returnnil }// Create new bucket. b := newBucket(typ,len(stk))
ただ、同じ処理（mysqlsrap）を繰り返しているのに、計測回数を増やすごとにプロファイルの情報が増えるというところがしっくりきていないところです（計測回数対しての線形増加なら「毎回新規でプロファイルを記録するんだな」とわかるのですが）。
計測結果を保存したheap.dumpにその記録されたプロファイル情報の詳細が残っているので、次回、そこから調べてみようと思っています。
まとめ
- 計測してみた結果、「http://localhost:6060/debug/pprof/ に表示されているheapの値が増える =メモリリークが発生している」ということではないことがわかった。
- http://localhost:6060/debug/pprof/ に表示されているheapの値はメモリ割り当てのタイミングで必要に応じて追加されるプロファイルの情報の数であることがわかった。
- そしてその中にはすでに開放されているものも含まれているということもわかった。
- 「なぜ、計測回数を増やすごとにプロファイルの情報の数が増えるのか」はわからなかった。
とりあえず、tcprxyにメモリリークがなさそうであることはわかったので良かったです。
