自作Golang Webアプリのメモリ枯渇バグを修正する
今年の初め、PicoShareというオープンソースアプリを作りました。ファイルを共有するためのシンプルなGolang製Webアプリです。メールに添付するには大きすぎるけれど、受取手にDropboxやGoogle Driveを使わせたくないファイルを送るために使っています。
数か月前、PicoShareサーバーが数日おきに落ちるようになりました。ログを確認すると、メモリ不足のエラーが出ていました。
当時はクラッシュをデバッグする時間がなかったので、サーバーのメモリを512MBから1GBに増やしてごまかしました。それでもクラッシュが続いたので、さらに2GBまで増やしました。
ただRAMを積み増してクラッシュをごまかすのは気持ちの良い解決策ではありません。そこでこの2週間、クラッシュの原因をデバッグし、その過程をTwitterで共有してきました。
現時点で、クラッシュの原因となっていた問題はすべて修正でき、GoやSQLite、デバッグについていくつか有用な教訓も得られました。
事の経緯をリアルタイムで追いたい方は、Twitterのスレッドをご覧ください。学んだことを整理してコンパクトにまとめた内容を読みたい方は、このまま読み進めてください。
前置き：ちょっと変わったSQLiteの使い方
PicoShareで私が下した奇妙なアーキテクチャ上の決断のひとつが、すべてのファイルデータをSQLiteに保存することでした。これはかなり珍しい選択です。通常、Webアプリケーションではアップロードされたファイルをデータベースではなくファイルシステムに直接保存するからです。特にアップロードされるファイルのサイズが無制限になり得る場合はなおさらです。
ファイルデータをSQLiteに書き込む利点は、PicoShareのアプリケーション状態がすべて単一のデータベースにまとまることです。それ自体は特別なことではありませんが、PicoShareはLitestreamというSQLiteデータベースをクラウドストレージにレプリケートするツールと連携するように設計しています。Litestreamのおかげで、PicoShareはバックアップとリストアを実質的に「タダ」で手に入れられます。サーバーを完全に吹き飛ばしてしまっても、どこにでも再デプロイでき（別のクラウドプロバイダーにさえ）、PicoShareはまったく同じ状態で目を覚まし、これまでと同じファイルを配信し続けます。
デバッグの過程
エラーの再現
PicoShareがクラッシュするのは数日に一度だけだったので、まずはクラッシュをより早く強制的に再現する方法を見つける必要がありました。
Flyの256MBメモリしかないインスタンスにPicoShareをデプロイし、大きなファイルをアップロードすることで、エラーを再現できました。テストファイルには、短編映画Big Buck Bunnyの高解像度版（269MBから618MBのもの）を使いました。
テストファイルには短編映画Big Buck Bunnyを使いました。大きなアップロードを試すのに十分なサイズだったからです。
618MB版を2つ並行してアップロードすると、1分ほどで必ずPicoShareがメモリ不足で落ちました。
プロファイリングツールでメモリ肥大化の原因を特定する
調査で最初のブレークスルーをもたらしてくれたのは、Litestreamの作者で最近Flyチームに加わったBen Johnson氏でした。Benは詳細なプルリクエストを作成し、たった1行のコードがPicoShareに大量のRAMを消費させていたことを説明してくれました。
Benはプロファイリングに精通しているので、新しいユニットテストを作ってテスト後のメモリをプロファイルすることで問題を再現できました。後でBenは同じ情報をもっと簡単に取得する方法を教えてくれたので、ここではそちらを紹介します。Benの当初の手法はプルリクエストで確認できます。
Goの標準ライブラリには、Webアプリケーションの問題をデバッグするための魔法のようなツールが用意されていることがわかりました。やることは、importにこの1行を追加するだけです。
_ "net/http/pprof"これでアプリを実行すると、多くの有用なデバッグ情報を含む/debug/pprof/というルートが利用できるようになります。
これほど簡単に追加できるとは驚きました。このWebインターフェースには興味深いデータがたくさんありますが、私が使ったのはheapです。使い方は、PicoShareに大きなファイルをアップロードしたあと、次のコマンドを実行するだけです。
go tool pprof \
-http=:8081 \
-alloc_space \
call_tree \
http://localhost:4001/debug/pprof/heapするとWebインターフェースが立ち上がり、次のようなグラフが表示されました。
下部にbytes makeSlice 63.99 MBとラベル付けされた大きな赤いブロックが見えます。これは、PicoShareが確保したRAMのうち64MBが、GoのmakeSlice関数によるものであることを意味します。
makeSliceは私のコードではなくGo標準ライブラリの関数です。PicoShareのどのコードがこのメモリ割り当てを引き起こしたのかを探すため、グラフを上にたどってPicoShareの関数を見つけました。
このチェーンの最後にあるPicoShareの関数はhandlers.fileFromRequestで、Go標準ライブラリの*Request.ParseMultipartFormを呼び出しています。この関数はmultipart形式のHTTPデータを解析するもので、PicoShareがファイルアップロードを受け付ける際にも使われています。
ParseMultipartFormはmaxMemoryというパラメータを受け取り、次のようにドキュメントされています。
リクエストボディ全体が解析され、ファイルパートのうち最大maxMemoryバイトまではメモリに保存され、残りは一時ファイルとしてディスクに保存されます。
PicoShareでの呼び出しは次のようになっていました。
r.ParseMultipartForm(32 << 20) // 32 MB32MBという上限を指定していたにもかかわらず、Goは64MBのRAMを確保していました。
BenがmaxMemoryパラメータを1 << 20（1MB）に下げてみたところ、ParseMultipartFormによるRAM使用量はわずか2.5MBまで減りました。
これは大幅なメモリ削減だったので、これで解決したと思いました。
しかし、Benの修正を入れたテスト版をデプロイしても、やはりクラッシュしました。
Benの修正後は、クラッシュするまでにより大きな負荷に耐えられるようになったので、効果はあったようです。それでも、大きなファイルを3つ並行してアップロードすると、サーバーは同じメモリ不足エラーで落ちてしまいました。
ParseMultipartForm呼び出し後のリソース解放
検索してみて、ParseMultipartFormにはもうひとつ落とし穴があることがわかりました。
ドキュメントには警告がありませんが、ParseMultipartFormでGoが確保したリソースを解放するために、呼び出し元がr.MultipartForm.RemoveAll()を呼ぶ必要があります。つまり、私はParseMultipartFormを呼ぶたびにメモリリークを起こしていたわけです。
追記（2022-08-11）：コメントでDamien Neil氏が、Goはこれらのリソースを自動的にクリーンアップすべきだと指摘してくれました。GoのHTTP/1実装では自動的にリソースが解放されますが、HTTP/2の実装でも一貫して動作するようにDamien氏がバグ修正を提出してくれました。
リークを修正するため、multipartのリソースをクリーンアップするようにコードを書き換えました。
multipartMaxMemory := 1 << 20 // 1 MiB
if err := r.ParseMultipartForm(multipartMaxMemory); err != nil {
return err
}
// Free form resources before returning from function.
defer func() {
if err := r.MultipartForm.RemoveAll(); err != nil {
log.Printf("failed to free multipart form resources: %v", err)
}
}()この修正は有望に見えました。リソースを明示的に解放したあと、Fly上のRAM使用量が大幅に減ったからです。
残念ながら、この修正を入れてもクラッシュは続きました。
ダウンロードの最適化
この頃、Dan Wilhelm氏がTwitterのスレッドをフォローし始めました。彼はGoを使ったことが一度もないにもかかわらず、腕まくりして自分の開発マシンでコードをいじり始めました。
DanはファイルをダウンロードするとRAM使用量が跳ね上がることに気づきました。これは奇妙なことでした。ダウンロードで大量のRAMを消費するはずがないからです。multipartフォームの解析は複雑なのでRAM肥大化の要因は多く考えられますが、ファイルを配信するのはかなり単純な処理のはずです。
PicoShareはすべてのファイルデータをSQLiteに328KBごとのチャンクに分けて保存しています。本来これはRAMを大量に使う処理ではないはずです。いくつかのチャンクをRAMに読み込み、クライアントに送信してからメモリを解放すればよいだけだからです。
Danは、PicoShareのファイルデータをデータベースから読み取るコードにバグを見つけました。どこかわかりますか。
func (fr *fileReader) populateBuffer() error {
if fr.offset == int64(fr.fileLength) {
return io.EOF
}
startChunk := fr.offset / int64(fr.chunkSize)
stmt, err := fr.db.Prepare(`
SELECT
chunk
FROM
entries_data
WHERE
id=? AND
chunk_index>=?
ORDER BY
chunk_index ASC
`)
if err != nil {
log.Printf("reading chunk failed: %v", err)
return err
}
defer stmt.Close()
var chunk []byte
err = stmt.QueryRow(fr.entryID, startChunk).Scan(&chunk)
if err != nil {
return err
}
// Move the start index to the position in the chunk we want to read.
readStart := fr.offset % int64(fr.chunkSize)
fr.buf = bytes.NewBuffer(chunk[readStart:])
fr.offset += int64(len(chunk)) - readStart
return nil
}バグはSQLクエリのWHERE句にありました。
WHERE
id=? AND
chunk_index>=?このクエリはファイルデータの1チャンクだけを取得するはずでした。ところが、対象のチャンクだけでなく、それ以降のすべてのチャンクを読み込んでいたのです。
修正は、>=を=に変えるだけでした。
WHERE
id=? AND
chunk_index=?余談：このコードを読んで、本来不要な場面でプリペアドステートメントを使っていたことにも気づきました。不要だったのですが、これがRAMに影響していたとは思えません。
Danの修正はダウンロード側のものだったので、アップロード時に起きていたクラッシュが直るとは期待していませんでした。実際直りませんでしたが、ダウンロードの配信パフォーマンスは劇的に改善しました。特に動画や音声のようなストリーミングコンテンツで、ファイル内の別の位置にシークしたときのレスポンスが格段に良くなりました。
SQLiteトランザクションの削除
Twitterのスレッドでは、PicoShareのSQLiteトランザクションがRAMを肥大化させているのではないかと指摘する人が何人もいました。
PicoShareがファイルデータをSQLiteに書き込む際、私はトランザクションの中で行っていました。目的は、データベースを常に一貫した状態に保つことでした。
トランザクションを使うことで、一部の書き込みが失敗したときにファイルの一部だけがデータベースに残るような状態になることをSQLiteが防いでくれます。また、ファイルの中身を書き込まずにメタデータだけを書き込んだり、その逆が起きたりすることも防げます。
検索すると、大きなSQLiteトランザクションがメモリ肥大化の原因になり得るという情報が見つかったので、試す価値はあると考えました。トランザクションを使わずに変更を即時コミットするようにしてみましたが、それでもRAMは肥大化しました。トランザクションは関係ないように思えました。
RAMの肥大化は問題ないが、クラッシュは問題だ
この時点で、私は3つの異なる角度からRAM使用量を測定していましたが、どれも互いに食い違っていました。
- Goのデバッグメトリクスが示す割り当て済みメモリ量
- VM内の
htop - VMホスト側のFlyのRAMメトリクス
RAM使用量を測るツールごとに結果が食い違っていました
特に、Goやhtopではほとんどメモリを使っていないと表示されているのに、Flyのメトリクスでは頻繁にRAMが上限張り付きになっていました。深掘りすればするほど、RAMの測定値が実際に観測されるクラッシュの挙動からかけ離れていくので、デバッグは苛立たしいものでした。
状況を一変させる洞察をくれたのはAndrew Ayer氏で、RAMの肥大化はおそらく見当違いだと指摘してくれました。
FlyのCEOであるKurt Mackey氏がスレッドに現れ、Andrewの仮説を裏付けてくれました。
つまり、Flyのメモリメトリクスにはページキャッシュが含まれていましたが、そのRAMは実行中のアプリケーションが必要とすればVMが回収すべきものだったのです。
これは大きな気づきでした。メモリ不足によるクラッシュを再現するのが難しかったため、私はRAMの肥大化をクラッシュの近似指標として使っていました。しかし、VMにプロセスを動かし続けるだけのメモリが残っている限り、RAMの肥大化自体は問題ではないのです。
ここで私はすべてを再評価する必要がありました。他の修正を退けたとき、それは無害なRAM肥大化が原因だったのか、それとも実際にクラッシュを観測したからなのか。
SQLiteトランザクションの再検討
Andrew Ayer氏の指摘を踏まえ、PicoShareのSQLiteトランザクションを再検討しました。トランザクションなしの実装を試したとき、私はクラッシュを見たのか、それとも単なるRAM肥大化だったのか。思い出せませんでした。
トランザクションなしの実装をもう一度試してみました。案の定、RAMは肥大化したもののPicoShareは動き続けました。618MBのファイルを3つ並行してアップロードしましたが、すべて成功し、PicoShareはHTTPリクエストを処理し続けました。
やりました！ついにパフォーマンス問題の根本原因にたどり着いたと思いました。
そう思ったのも束の間でした…
サーバーを一晩放置し、翌朝確認すると、同じメモリ不足でクラッシュしていました。
SQLiteのVACUUMをなくす
夜間のクラッシュは、データベースファイルを圧縮して未使用のディスク領域を回収するSQLiteのVACUUMコマンドが関係しているのではないかとすぐに疑いました。
クラッシュ時にPicoShareサーバーを使っていた人は誰もいませんでしたが、PicoShareの定期的なデータベースメンテナンスのタイミングと一致していました。PicoShareは7時間ごとに期限切れのエントリをデータベースから削除し、未使用のディスク領域を回収するためにVACUUMを実行しています。
サーバーでVACUUMコマンドを実行して試してみると、確かにメインの.dbファイルのサイズは減りましたが、SQLiteのライトアヘッドログのサイズが増えていました。
この時点で、BenからそもそもなぜVACUUMが必要なのかと聞かれました。
たしかに、なぜ私はそんなことをしているんだろう？
PicoShareを最初に公開したとき、ファイルを削除してもディスク容量が戻らないという苦情がユーザーから寄せられました。私はFly VMの固定ディスクボリュームでPicoShareを運用しているので、自分には影響がありませんでした。ディスクをどれだけ使っても問題ないからです。でも、定期的なVACUUMを追加するのは簡単だったので、そうしました。
よく考えた結果、PicoShareの挙動を変更し、VACUUMはデフォルトでオフにして、必要に応じてコマンドラインフラグで有効にできるようにしました。
dbPath := flag.String("db", "data/store.db", "path to database")
vacuumDb := flag.Bool("vacuum", false, "vacuum database periodically to reclaim disk space")
flag.Parse()成功：256MBのRAMで動作するPicoShare
VACUUMをデフォルトで無効にし、他のパフォーマンス修正も適用したことで、PicoShareはついに少ないRAMでも安定して動作するようになりました。
256MBのRAMしかないFly VMで、PicoShareを24時間クラッシュなしで動かし続けることができました。
過去24時間の稼働率は100%
その他に学んだこと
上で述べたことに加え、このデバッグの冒険の中でいくつかの有用な副次的な教訓も得られました。
ビルド・テストのループを最適化する
もっと早くやっておけばよかったと思うことのひとつが、ビルド・テストのループを最適化することでした。仮説をひとつ試すたびに、私の手順は次のとおりでした。
- 変更をFlyにデプロイする（2〜3分）
- 大きなファイルをアップロードする（1〜2分）
- FlyのRAMメトリクスが追いつくのを待つ（30〜60秒）
つまり、1回の変更を試すだけで最大6分かかり、しかも各ステップで手作業が必要でした。コード変更を書く時間は含めずに、です。
当初はRAMを制限したDockerコンテナでPicoShareを動かしてみましたが、クラッシュは一度も起きませんでした。
RAM_LIMIT="64m"
PORT=3001
PS_SHARED_SECRET="somesecretpass"
docker run \
--memory "${RAM_LIMIT}" \
--env "PORT=${PORT}" \
--env "PS_SHARED_SECRET=${PS_SHARED_SECRET}" \
--publish "${PORT}:${PORT}/tcp" \
--name picoshare \
mtlynch/picoshare:1.1.7$ docker stats
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS
1ababd398113 picoshare 3.82% 63.68MiB / 64MiB 99.50% 278MB / 208MB 6.09GB / 7.1MB 21なぜPicoShareがDockerと実際のVMで挙動が違うのか、今でもよくわかりませんが、おそらくDockerはVMほど厳密にRAM使用量を制限していないのだろうと推測しています。
Dan Wilhelm氏がPicoShareをローカルで動かしてRAM使用量を観察し、どれだけ進捗があったかを報告してくれたとき、変更のたびにFlyにデプロイしてどれだけ時間を無駄にしていたかに気づかされました。自宅のVMサーバーでもPicoShareを動かしてみましたが、FlyのようにクラッシュしたりRAMが肥大化したりすることはありませんでした。
最終的にうまくいったのは、Fly上に自分専用の開発環境を作る方法でした。DockerfileにPicoShareのソースと開発ツールを含めてFlyにデプロイしました。あとはfly ssh consoleでサーバーにシェルを開き、コード変更を素早くテストできました。
FlyのRAMメトリクスが更新されるまで30秒ほどの遅延があるため、超高速というわけではありませんでしたが、変更のたびに一からデプロイするよりは大幅に改善されました。
わかりやすいgitブランチ名とコミットメッセージで記録を残す
この調査の中で見つけた有用なテクニックのひとつが、仮説ごとに専用のgitブランチで検証し、結果をコミットメッセージに記録する方法でした。
さまざまな仮説が飛び交う中で、それぞれのアイデアを試したときにコードがどんな状態だったかを覚えておくのは困難でした。例えば、あるときはデバッグ中に自分で混入させてしまった新しいバグのせいでクラッシュしていました。
コードがどんな状態で、何をどうテストしたかの記録を残すことで、思考を整理し、同じ作業を繰り返すのを避けることができました。
Goの計測ツールはcgoでのメモリ割り当てを見られない
私が最初に行ったデバッグのステップのひとつは、runtime.ReadMemStatsから取得したRAMメトリクスを表示するページをPicoShareに追加することでした（後でnet/http/pprofの方が優れていることに気づきました）。
James Tucker氏が、この測定ではcgo経由で確保したリソースは除外されると指摘してくれました。
実際、私はcgo経由でSQLiteを使っていました。PicoShareではGoで最も人気のあるSQLiteライブラリであるmattn/go-sqlite3を使っています。
cgoを使うとGoが正確なパフォーマンスメトリクスを表示できなくなるのは当然です。Goから外部のCコードを呼び出している場合、Goはその外部コード内のリソースを追跡できないからです。
これを回避するため、SQLiteの純粋なGo実装であるmodernc.org/sqliteを試してみました。しかし、なぜか純粋なGoコードでもリソースリークは見えませんでした。
Flyのディスクは驚くほど高速
あるとき、Twitterのコメントで、ディスク書き込みでRAMを使い果たしているのではないかと指摘されました。PicoShareがFly VMのディスクに対して、ディスクが物理メディアに書き込める速度より速く書き込んでいたら、データはRAMにキューイングされることになります。
この説を検証するため、これまで使ったことのなかったfioというディスクベンチマークツールを使いました。書き込み速度が3353MB/sと表示され、クラウドVMとしては信じられないほど速かったので、ツールの使い方が間違っているのかと思いました。参考までに、これは自宅のNASサーバーで同じテストをしたときの約30倍の速さです。
Kurt Mackey氏が、Flyのローカルディスクはエンタープライズ向けNVMeドライブなので、その測定値はおそらく正しいと確認してくれました。
行き止まりだった試み
調査が常に順調に前進していればよかったのですが、実際には何度も道を誤り、何の成果もない仮説を追いかけました。ここでは、そんな行き止まりのいくつかを紹介します。
Litestreamを疑う
デバッグの第一原則は、問題は自分のコードにあると考えることです。しかし、私はここでその原則を破ってしまいました。部分的には、これらのバグを追いかけるのがどれだけ大変かを恐れたからです。
とはいえ、Litestreamを疑うのにも正当な理由はありました。PicoShareはSQLiteを変わった方法で使っていますが、1GBのデータをSQLiteに保存すること自体はそれほど奇妙なことではありません。Litestreamは比較的新しく、SQLiteを斬新な方法で使っているので、クラッシュの原因がLitestreamにあると考えるのはそれほど飛躍したことではありませんでした。
Litestreamを疑ってはいたものの、メンテナーであるBen Johnson氏に余計な仕事を増やしたくはありませんでした。PicoShareはLitestreamにとって特殊なユースケースであることはわかっていましたし、問題を切り分けるためのシンプルな再現手順も持っていなかったからです。
しかし5月にFlyがLitestreamを買収し、Benをメンテナーとして雇用しました。これはLitestreamとFlyの両方に関わることなので、Benに相談する絶好のタイミングに思えました。
私はLitestreamにバグを報告し、これまで試したことと、なぜLitestreamが関係していると思ったかを説明しました。そして15分後、Litestreamを無効にした状態でもPicoShareをクラッシュさせることができたので、そのバグはクローズしました。
とはいえ、Litestreamに対してissueを立てたことは有用でした。詳細なバグレポートを書けるほど厳密に問題に向き合わざるを得なくなったからです。そしてそれがBenの好奇心を刺激し、Litestreamが原因ではないと明らかになった後も、彼は多くの有用なアドバイスをくれました。
Flyを疑う
ローカルのVMやDockerではクラッシュを再現できなかったため、問題はFly側にあるのではないかと疑い始めました。私は特に奇抜なことをしているわけではなかったので、他のFlyユーザーが誰もRAM不足でデプロイが落ちることに気づいていないとしたら奇妙だと思い、可能性は低いと考えていました。
それでも、Flyの可能性を排除したかったので、AmazonのマネージドDockerコンテナサービスであるLightsailにPicoShareをデプロイしました。そこには256MBのRAMオプションがなかったので、512MBのインスタンスにデプロイしました。数分以内にそこでもクラッシュを再現でき、Flyが原因ではないことがわかりました。
/tmpはRAMディスクではない
Twitterのスレッドでは、Flyが一時ディレクトリをRAMディスクとしてマウントしているのではないかと指摘するコメントがいくつかありました。GoのParseMultipartForm関数はファイルアップロードを一時ディレクトリに保持するので、もしFlyが一時ディレクトリをRAMディスクとしてマウントしていたら、通常のファイルアップロードでRAMが枯渇する説明がつきます。
しかしlblkを実行しても、/tmpやその他一時ディレクトリがRAMディスクである兆候は見当たりませんでした。システムには通常のディスクがあるだけのように見えました。
$ lsblk
NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINTS
vda 254:0 0 128M 0 disk
vdb 254:16 0 8G 0 disk /
$ du -h /tmp/*
149.3M /tmp/multipart-338465586
7.66 /tmp/test1自作のmultipartフォームリーダーを書く
Go標準ライブラリのParseMultipartForm関数が、ドキュメントされた上限より多くのメモリを消費しているように見えたのは危険信号でした。また、ParseMultipartFormを呼び出してバイト列を破棄した場合でも、RAMが上限に達することに気づきました。
ParseMultipartFormの問題を回避できないか試すため、自分のユースケース専用に手作りのmultipartリーダーを自前で書いてみました。
残念ながら、自作のmultipartリーダーは標準ライブラリより優れた性能を発揮しませんでしたが、より低レベルでmultipartデータをいじるのは楽しい経験でした。
アップロードのスロットリング
データをよりゆっくりアップロードすればRAMに影響があるのか気になりました。Chromeで3G速度をシミュレートしてクライアント側でアップロードをスロットリングしてみましたが、PicoShareの挙動は変わりませんでした。
サーバー側でもディスクへの書き込み速度を落とすためにスロットリングを試しましたが、こちらも効果はありませんでした。
ただ、GoでI/Oをスロットリングするのがいかに簡単かは学べました。io.Readerインターフェースを使っている場合、次のようにReaderをスロットリング用のリーダーでラップするだけです。
import "github.com/juju/ratelimit"
...
throttleRate := 1 << 20 // 1 MB
bucket := ratelimit.NewBucketWithRate(float64(throttleRate), throttleRate)
throttledReader := ratelimit.Reader(reader, bucket)
w := file.NewWriter(tx, metadata.ID, d.chunkSize)
if _, err := io.Copy(w, throttledReader); err != nil {
return err
}PicoShare 1.2.0
週末に、この調査で見つかったすべてのパフォーマンス問題の修正を含むPicoShareの1.2.0リリースを公開しました。
謝辞
この問題の調査に協力してくれたすべての方に感謝します。特に並外れた助力をいただいた以下の方々に、心からお礼を申し上げます。