インフラ・ストリーミングチームの id:udzura （@udzura）です。今回は、Goミドルウェアのメモリリークを見つけて解決する際に、どのようなプロセスを踏んでいったかを解説します。
Go製のミドルウェアの概要
ミラティブでは、Webアプリケーションのみならず、ミドルウェアに相当する部分についても必要なものは内製しています。その中の一つに、社内で「Radisha」と呼んでいる各種集計とキャッシュなどを行うためのミドルウェアがあります。Radishaは以下のような特徴を備えています。
- GET、SET、SETEXなど基本的なRedis互換のコマンドを実装している。そのため、既存のRedisクライアントライブラリから操作が可能である。
- ランキング集計、一定時間内のアクセス集計などが行えるよう、Redis にない独自のコマンドを実装している。
- 高い可用性を志向しており、オンメモリのデータは Raft を用いてレプリケーションされる。
ちなみにRadishaという名前は特徴であるRedis + Raft + HA(High Availability)から付けられました。
このミドルウェア自体のアーキテクチャなど、詳細な解説は、別の記事に譲ることとします（お楽しみに！）。今回はメモリリークの解決にテーマを絞ります。
なお、今回の記事執筆にあたり、確認や検証を行った環境は以下となります。
Goのバージョン
- Go 1.17.10
OS
- Flatcar Container Linux 2605.9.0 x86_64 / Kernel 5.4.81-flatcar
- Ubuntu 20.04.1 aarch64 / Kernel 5.8.0-63-generic （最後のtraceの検証のみ）
検証中に発生したメモリリーク
このRadishaを検証環境で動作させて、ある程度負荷を掛けつつ挙動を確認していたところ、以下のような問題が発生しました。
- 時間経過とともに、プロセスのResident Set Size（RSS）が肥大化してしまう
- アクセスが少ない状態でも、数日の間にRSSが2GBを超過し、減る様子が見られない
- メモリの肥大化に伴ってなのか、SETなどの書き込み系コマンドのリクエストが時々遅くなってしまう
- 通常数msで完了するところが、数百ms〜数秒かかることがある
メモリリークが発生し、それがリクエストの遅延につながっているのではないかと考えました。そしてログを仕込んだり、色々と検証しているうちに、どうやら長時間書き込みのリクエスト（SET、DELなど）が行われると徐々に肥大していくようだということが分かりました。
以下の内容は実際にメモリリークを確認した際の手順ではありませんが、分かりやすいように実験をします。メモリリークが起こっていたバージョン（バージョンA とします）を起動して、一定時間SETコマンドを送り更新を行った際のメモリ（RSS）の増加を観測してみます。
具体的には、GoでRedisのための単純なベンチマークツールを作成し、10分間、毎分150,000回程度のSETコマンドを発行しました。RSSについては以下のコマンドで取得できる、Private_Clean/Private_Dirty/Private_Hugetlbの合算値を利用し、実際に自プロセスで持っているメモリを計算しました。
PID=$(pidof radisha) # RadishaのプロセスID
RSS=$(sudo cat /proc/$PID/smaps | awk '/^Private/ { sum += $2 } END { print sum }')
以下がその結果です。
バージョンAでの結果は青色のグラフです。比較のために修正したバージョン（バージョンB とします）での結果を併記しています（オレンジ）。このように、バージョンAの段階ではSETコマンドを受け取れば受け取るほどメモリが肥大化していく現象が見られました。
また、メモリ肥大に伴ってなのか、時々書き込み操作が極端に遅くなる現象が起こりました。バージョンAで上記のベンチツールで大量のアクセスを行うとともにリクエストの所要時間を記録したところ、100ms 以上のリクエストがしばしば発生し、中には1秒以上、最大では2.8秒かかるリクエストが発生する状態になっていました。以下に、全リクエストの所要時間の統計情報を記します。
Count: set=1466934 failed=0 success%=100.000
Elapsed: 9m59.488855576s
Set per min: 146818.476/m
AVG | 50%ILE | 90%ILE | 95%ILE | 99%ILE | 99.5%ILE | MAX | STDDEV
----------+---------+---------+---------+---------+----------+------------+-----------
1.925ms | 1.027ms | 2.307ms | 3.160ms | 3.160ms | 8.020ms | 2896.521ms | 28.554ms
----------+---------+---------+---------+---------+----------+------------+-----------
bin |
1ns ~ | (0 0.00%)
10ns ~ | (0 0.00%)
100ns ~ | (0 0.00%)
1µs ~ | (0 0.00%)
10µs ~ | (0 0.00%)
100µs ~ | ***************************** (706304 48.15%)
1ms ~ | ******************************** (756642 51.58%)
10ms ~ | (2999 0.20%)
100ms ~ | (609 0.04%)
1s ~ | (380 0.03%)
10s ~ | (0 0.00%)
ちなみにバージョンBでの同様の全リクエストの所要時間の統計情報を記します。遅延が著しく改善されていることがわかります。
Count: set=1548664 failed=0 success%=100.000
Elapsed: 9m59.274301758s
Set per min: 155053.937/m
AVG | 50%ILE | 90%ILE | 95%ILE | 99%ILE | 99.5%ILE | MAX | STDDEV
----------+---------+---------+---------+---------+----------+-----------+----------
0.794ms | 0.628ms | 1.247ms | 1.675ms | 1.675ms | 5.291ms | 653.396ms | 1.867ms
----------+---------+---------+---------+---------+----------+-----------+----------
bin |
1ns ~ | (0 0.00%)
10ns ~ | (0 0.00%)
100ns ~ | (0 0.00%)
1µs ~ | (0 0.00%)
10µs ~ | (0 0.00%)
100µs ~ | ******************************** (1271730 82.12%)
1ms ~ | ****** (275707 17.80%)
10ms ~ | (1195 0.08%)
100ms ~ | (32 0.00%)
1s ~ | (0 0.00%)
原因箇所の特定
ということで、メモリリークが存在することは見えてきたので、まずはその原因の追求から始めることにしました。
原因を特定するために、検証環境で起動しているインスタンスをもとに、Goのヒープの状況を分析します。
Goのヒープの状況を把握するにあたっては、pprofが非常に強力なツールです。今回の記事もpprofをどう利用したかを中心に書いていきます。
まず、ミドルウェア内でpprofを有効にします。
import ( "net/http" _ "net/http/pprof" "runtime" ) // urfave/cli で起動されるアクションの起点 func actionStart(c *cli.Context) error { //... runtime.SetBlockProfileRate(1) go func() { log.Printf("info: start profiler on [0.0.0.0]:6050 %v", http.ListenAndServe("[0.0.0.0]:6050", nil)) }() }
その上でミドルウェアをpprof有効のバージョンに入れ替えます。起動してすぐの段階でのヒープの状況をこの段階で取得します。
$ docker run -v /tmp/pprof:/tmp/pprof --net=host golang:1.17 container$ go tool pprof http://localhost:6050/debug/pprof/heap File: radisha-sample Type: inuse_space Time: Jul 22, 2022 at 10:46am (UTC) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
以下のように top コマンドでヒープの様子が確認できます。この際、 pprof/pprof.radisha-sample.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz のようなファイルが同時に作成されるので消さないようにします*1。
デフォルトでは inuse_space モード、すなわち利用中でプロセスに残っているメモリーのサイズの統計を表示します。また、flatはその関数のみで利用しているメモリのみ、cumはその関数から呼び出した関数も含んだ値です。通常はflatを中心に見ることになります。
(pprof) top Showing nodes accounting for 134.15MB, 98.53% of 136.15MB total Dropped 13 nodes (cum <= 0.68MB) Showing top 10 nodes out of 26 flat flat% sum% cum cum% 127.08MB 93.34% 93.34% 127.08MB 93.34% github.com/octu0/cmap.newDefaultCache (inline) 4MB 2.94% 96.28% 4MB 2.94% github.com/syndtr/goleveldb/leveldb/memdb.New 1.50MB 1.10% 97.38% 1.50MB 1.10% runtime.malg 1MB 0.73% 98.12% 1.50MB 1.10% github.com/octu0/chanque.(*Executor).execloop 0.57MB 0.42% 98.53% 127.64MB 93.76% github.com/octu0/cmap.newSlab (inline) 0 0% 98.53% 127.64MB 93.76% github.com/internal-lib/foo.Init 0 0% 98.53% 132.14MB 97.06% github.com/internal-lib/server.actionStart 0 0% 98.53% 127.64MB 93.76% github.com/internal-lib/database.New 0 0% 98.53% 127.64MB 93.76% github.com/octu0/cmap.New 0 0% 98.53% 4MB 2.94% github.com/syndtr/goleveldb/leveldb.(*DB).mpoolGet
時間を置いて、メモリが肥大化してきたら再び同じコマンドでヒープを取得します。topに出てくる関数が変わっていました。
(pprof) top Showing nodes accounting for 363.81MB, 96.10% of 378.55MB total Dropped 40 nodes (cum <= 1.89MB) Showing top 10 nodes out of 78 flat flat% sum% cum cum% 127.08MB 33.57% 33.57% 127.08MB 33.57% github.com/octu0/cmap.newDefaultCache 93MB 24.57% 58.14% 93MB 24.57% github.com/internal-lib/loop.runWriteApplier 90.01MB 23.78% 81.91% 91.51MB 24.17% runtime.systemstack 13MB 3.43% 85.35% 13MB 3.43% github.com/internal-lib/database.(*simpleCounter).incrementLocked 12.06MB 3.18% 88.53% 12.06MB 3.18% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get 8.06MB 2.13% 90.66% 10.73MB 2.83% github.com/syndtr/goleveldb/leveldb.(*Batch).appendRec 8MB 2.11% 92.78% 8MB 2.11% github.com/syndtr/goleveldb/leveldb/memdb.New 6.02MB 1.59% 94.37% 7.03MB 1.86% github.com/tidwall/redcon.NewReader 3.51MB 0.93% 95.30% 3.51MB 0.93% github.com/internal-lib/lib.(*conn).Read 3.06MB 0.81% 96.10% 3.06MB 0.81% github.com/syndtr/goleveldb/leveldb/memdb.(*DB).Put
差分を取得したい際は、 -diff_base をいうオプションを指定することができるので、先ほど保守しておいた起動直後のpprofファイルを指定して確認します。
$ go tool pprof -inuse_space \ -diff_base=pprof/pprof.path-to-first-pprof-file.001.pb.gz pprof/pprof.path-to-second-pprof-file.002.pb.gz
以下のように特定の関数が非常に上にくることがわかりました。
File: radisha-sample Type: inuse_space Time: Jul 22, 2022 at 10:46am (UTC) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 235.40MB, 172.90% of 136.15MB total Dropped 30 nodes (cum <= 0.68MB) Showing top 10 nodes out of 73 flat flat% sum% cum cum% 93MB 68.31% 68.31% 93MB 68.31% github.com/internal-lib/loop.runWriteApplier 90.01MB 66.11% 134.42% 90.01MB 66.11% runtime.systemstack 13MB 9.55% 143.97% 13MB 9.55% github.com/internal-lib/database.(*simpleCounter).incrementLocked 12.06MB 8.86% 152.83% 12.06MB 8.86% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get ...
具体的なリークの箇所の特定
原因となっていそうな関数が判明しました。ここで、その関数をひたすら目視して怪しい箇所を探してもいいのですが、より効率の良い方法としてpprofの list コマンドを使い、リークしている箇所を特定すると良いでしょう。
利用するために、ソースコードを含んだコンテナを用意しないといけません。ミドルウェア用のコンテナにはコンパイル済みのバイナリしか含まれていませんので、ビルドの際に行ったMultipart Buildに合わせたパスにCOPYするだけのコンテナイメージを作ります。
FROM golang:1.17 WORKDIR /build COPY . ./ # ライブラリのコードも含めるためダウンロード RUN go mod download
このコンテナを起動し、先ほどのpprofファイルを（Volume Mountなどで）持ってきて同じように go tool pprof -inuse_space ... を起動します。
この状態であればpprofのコンソールの中で list というコマンドを使うことができます。以下が結果の抜粋です。
ROUTINE ======================== github.com/internal-lib/loop.runWriteApplier in /build/internal-lib/loop.go
93MB 93MB (flat, cum) 68.31% of Total
. . 633: forNextTick = time.Now()
. . 634: }
. . 635: countTick += 1
. . 636: }
. . 637:
7MB 7MB 638: reqSize := 0
15.50MB 15.50MB 639: dataSize := 0
70.50MB 70.50MB 640: defer func() {
. . 641: elapsed := time.Since(start)
. . 642: if (100 * time.Millisecond) < elapsed {
. . 643: m.log.Noticef("write logs are delayed:%s reqs:%d size:%d", elapsed, reqSize, dataSize)
. . 644: }
. . 645: }()
defer を行っている箇所が一番メモリを増加させているようです。
ここでそもそも、runWriteApplierという関数が何をしているかという話をします。この関数は、Radishaに対するSETなどの書き込み操作のログを、チャンネル経由で受け取ってRaftのLogとして適用する操作をループで行っている関数です。Raftのレプリケーションでは変更の操作をLogという形でリーダーからフォロワーノードに送り込む操作を行います。また、単一のノードで動作している場合でもLogを溜め込む必要があります。
処理の概要は以下のようになります。エラー処理もスキップして単純化したコードですが、ループの中でリクエストを受け取ってそれを一通りRaftのLogに流し込んでいるイメージを持っていただければと思います。
func runWriteApplier() { // 初期化処理 // ... for true { reqSize := 0 dataSize := 0 defer func() { log.Printf("このtickでapplyされたリクエスト: %d, %d", reqSize, dataSize) }() reqs = make([]request, 0) // リクエストが来るまではブロック firstReq := <-machine.ch reqs = append(reqs, firstReq) // 一回のバッチで来たリクエストをまとめてapplyしようとする for isEmpty(machine.ch) { reqs = append(reqs, <-machine.ch) } reqSize = len(req) dataSize = getSize(req) // reqsを全てapply for _, req in range reqs { raft.Apply(req) } } }
この際、定期的にRaft Logに適用したレコードの件数や、データサイズをログに出すようにしていました。そしてそのログを出す処理をdeferで遅延させてようとしていました。
しかし、deferはそもそも関数のブロックの中で宣言するものですが、今回はdeferをfor loopのブロックの中で宣言していました。ループを一周回っても関数を抜けるわけではないのでdeferは実行も解放もされません。そしてこのループは書き込みリクエストがあるたびに回り続ける無限ループなので、SETコマンドを大量に発行すると、deferのみがされ続けてリソースがリークし、メモリが肥大化していた、ということがわかりました。
解決策として、deferを外してループの最後で素直にログを表示するようにしました。こうして、最初にグラフで掲示した通り、次のバージョン以降ではメモリリークは解決しました。
メモリ肥大とリクエストの遅延の関係の調査
今回のメモリリークの修正と一緒に、リクエストの遅延もほぼほぼ再現しなくなりました。最後に、なぜメモリが肥大した結果リクエストが遅延するようになったかについてもう少し背景を探りたいと思います。
遅延の状況について知るために、Goroutineそれぞれの動作状況を可視化してみます。
deferによるメモリリークを再現させ、RSSが1GB程度に到達したRadishaに少しずつSETリクエストを流すと、定期的にリクエストが遅延します。その状態にしてから、以下のコマンドでGoのtraceを一定時間分取得します。今回は50〜60秒ごとに遅延が発生したので、2分程度取得しました。
$ curl http://localhost:6050/debug/pprof/trace?seconds=120 > trace.out
このファイルを利用して以下のコマンドを実行すると、Goroutineの可視化のためのツールが立ち上がり、ブラウザでアクセスできるようになります。traceファイルがあれば実行はMac上など別ので構いません
$ go tool trace ./trace.out
今回、遅延が起こった前後のGoroutineの様子を見てみます。
まず、GCが1秒近くかかる状態になっていることがわかります。
ドリルダウンしてみると、GCのMarkフェーズが最初8コアで動いているのですが、それでもマークしきれなかったためかその後もGC(dedicated)のルーチンが動いており、その間は他のGoroutineがほとんど動いていない状態が観測できました。
このバージョンのGoのGCのMarkフェーズはConcurrentに動くはずですので、ここでブロックしてしまう現象は不思議でした。実際、deferではなくmapの参照をループ内に残した状態を作って敢えてメモリリークを起こし、同じようにGCのオーバヘッドを確認しましたが、GCのルーチンが他の処理をブロックし続ける状態は観測されませんでした。
今回はdefer処理がリークしていることに関係があるのかもしれませんが、ここの調査は宿題です。
いずれにせよ今後の開発や運用時にも引き続きメモリの状況、ことdeferのリークには気を配り、例えばLintの導入などすると良さそうです。
まとめ
社内のミドルウェアを例にメモリリークを発見するまでの流れを書きました。今回のメモリリーク箇所は、loopの中でdeferするといううっかりやりがちな箇所ではありましたが、再現手順を確立し、pprofを正しく使うことで発見することができました。
ミドルウェアを開発し本番環境に出す前には、以下のような流れで着実に問題を潰していく必要があると思います。
- 問題が起こらないか、ある程度の負荷（可能なら本番環境同等の負荷）をかけた状態で事前検証する
- 問題が起こった場合、再現する手順を明確にする
- 内部のさまざまな情報を確実に計測する
この時、検証環境で起こるような問題は、条件さえ揃えば本番環境でも起こってしまうので、小さな兆候であっても見逃さないように調査します。
Goでミドルウェアを書いて上記のような調査と検証を行う場合、pprofは問題の計測と特定に非常に役に立つと思います。pprofは今回紹介したヒープの可視化の他にも、フレームグラフの作成やブロックしているGoroutineの検知などさまざまな機能があり、引き続き使い方に習熟したいと考えています。
We are hiring!
ミラティブではミドルウェアのみならず、技術を深掘りしたいエンジニアを募集しています！ 少しでも興味がああれば是非カジュアルにお声がけください。
*1:今後の例では、一部のパッケージや関数名をダミーのものにしています
