tcprxyというTCPプロキシを作っています。
github.com
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の値 のようです。
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
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
}
b := newBucket(typ, len(stk))
ただ、同じ処理（mysqlsrap）を繰り返しているのに、計測回数を増やすごとにプロファイルの情報が増えるというところがしっくりきていないところです（計測回数対しての線形増加なら「毎回新規でプロファイルを記録するんだな」とわかるのですが）。
計測結果を保存したheap.dumpにその記録されたプロファイル情報の詳細が残っているので、次回、そこから調べてみようと思っています。
まとめ
とりあえず、tcprxyにメモリリークがなさそうであることはわかったので良かったです。