🎢

Cloud Profilerを使ってメモリリークを特定したい!

2023/12/19に公開

この記事は Magic Moment Advent Calendar 2024 14 日目の記事です。

こんにちは!
Magic Moment でエンジニアをしている 大塚 です。

私事ですが、1年間毎日トマトジュースを飲み続けたら2kgの減量に成功しました。トマトジュースはいいぞ。

さて、弊社 Magic Moment の Tech チームでは毎週 システムモニタリング を行い サービスのパフォーマンスやリソース使用量を観察し、問題があれば改善を行っています。
去年のアドベントカレンダーでは goroutine leak を発見して解消する記事を書きましたが、今年はリソースの開放漏れによるメモリリークを特定して解消に奮闘する話をしたいと思います。

メモリリークを観測

ある日のシステムモニタリングで、サービスのメモリ使用率が上昇し続けていることに気づきました。
以下は Cloud Monitoring で観測したメモリ使用率のグラフです。

日々メモリ使用率が上昇し続けている

原因の特定する

特に新しい機能をリリースしたタイミングでもなかったため、怪しい箇所がぱっと分からずCloud Profilerで詳細を確認することにしました。
Cloud Profilerについては弊社エンジニアの Miyake が書いたCloud Profilerを導入してパフォーマンス改善をした話 をチェックしてください。

Cloud Profiler でヒープの使用量を確認してみます。
ヒープの使用量については公式ドキュメントによるとこう書かれています。

プロファイルの収集時にプログラムのヒープ内に割り当てられているメモリの量です。一定期間にわたってデータが収集される他のプロファイル タイプとは異なり、このプロファイル タイプでは、単一の時点でヒープ使用量が収集されます。
ヒープ使用量をプロファイリングすることで、プログラムの非効率性やメモリリークの可能性を見つけることができます。ヒープ割り当てをプロファイリングすると、ガベージ コレクタの処理が最も多い割り当てを特定できます。

つまり、ある時点でヒープに割り当てられているメモリの量を確認できということは、別の時点同士で見比べればメモリリークの原因を特定しやすいということです。

今回 メモリリーク が観測されたサービスのある時点のヒープ使用量は以下のようになっていました。

Cloud Profilerで確認したヒープ使用量

そして以下が3日後のヒープ使用量

Cloud Profilerで確認したヒープ使用量

お気づきの通り、明らかに使用量が増加している関数を確認することができます。この関数の中でプロファイリングを確認していきます。

ここまで来ると、ライブラリやフレームワークの他にプロダクションコードの関数名などわかってくるため、一部モザイク処理をしています。

Cloud Profilerで確認したヒープ使用量

以下が3日後

Cloud Profilerで確認したヒープ使用量

画像の通り、firestore にクエリを投げる処理のヒープ使用量が増加しています。
ここで、firestore へのコネクションやリソースが適切に開放されてないのかもしれないと予想します。

修正を試みる

関数名まで特定できるので該当の関数で firestore にクエリを投げる処理を確認してみます。

iter := client.
    Collection(xxx).
    Doc(xxx).
    Collection(xxxx).
    Where("xxxId", "==", xxxID).
    Documents(ctx)

// 中略

return hoge, nil

cloud.google.com/go/firestoreのパッケージを利用して、firestore からクエリ結果のイテレータを取得しているコードです。
このクライアントライブラリのドキュメントによると、イテレータを取得した後は必ず Stop を呼んでリソースを開放する必要があるとのことです。

というわけで、以下のようにコードを修正しました。

iter := client.
    Collection(xxx).
    Doc(xxx).
    Collection(xxxx).
    Where("xxxId", "==", xxxID).
    Documents(ctx)

defer iter.Stop()

// 中略

return hoge, nil

結果

リソースの適切な開放を行った結果を確認してみます。

以下の画像は該当の関数のヒープ使用量のプロファイリング履歴です。

Cloud Profilerで確認したヒープ使用量

ガクッと落ちたタイミングが修正のリリースしたタイミングです。

気持ちいいくらいにヒープ使用量が安定しているのが確認できました。

まとめ

今回は Cloud Profiler を使ってメモリリークを特定し、修正するまでの流れを紹介しました。

やっぱり外部のサービスに接続してデータを扱う際はリソースの適切な開放を心がけることが大切ですね。
提供されている SDK やクライアントライブラリを利用する際は、ドキュメントを読んで理解しないとですね。

また、今回のメモリリークはリリース後すぐに発覚したわけではなく、利用量が増えるにつれて発覚したため、定期的なシステムモニタリングを行うことの重要性を再認識しました。


さて、次回のアドベントカレンダーは scent-y の「Custom Terraform Provider はじめて作成してみた」です。
お楽しみに!

Discussion