プラットフォームチームの桝井です。
ある日、なぜか突然特定のバッチの実行時間が2倍になる事象が発生、
どうやらメモリリークが起きていそうとメンバーから共有があり、詳しくは調査することになりました。
本記事では謎のメモリリークが起きたときどう対応していくのか？をご紹介したいと思います
前提
- プロダクトコードを模した説明用の模擬コードです。（実際には動かないかもしれません。）
- 環境はPHP8.2, Laravel11.45
🔍シンプルな調査
該当するバッチのソースコードのうち巨大なデータ・オブジェクトを扱っているような怪しい箇所を見つけアタリをつけます。
今回は以下のようなソースコードが怪しいとアタリをつけました。
<?php class NotificationHandler { // ...略 public function sendSomethingNotification(CarbonImmutable $datetime): void { // 巨大なデータ $query = HugeSomethingModel::select('id') ->where('generated_date', '=', $datetime->format('Y-m-d')); $query->chunk(10000, function (Collection $records) use ($datetime) { $data = $this->getRelationData($records->pluck('id'), $datetime); $somethingContents = $this->probableSomethingRun($data); $this->sendEmail($this->email, $somethingContents, $this->sqs); } } // ...略 }
そして以下のようなデバッグ用メソッドを作成または 直接該当箇所に記述することが多いのではないでしょうか。
<?php class NotificationHandler { // ...略 private function memoDebug($label): void { Log::info( $label, [ 'usage' => (int)memory_get_usage() / (1024 * 1024), 'peak' => (int)memory_get_peak_usage() / (1024 * 1024), ] ); } }
それらを先ほどの怪しいところに仕込み、ステージなど開発環境でバッチを実行・測定を行います。
<?php class NotificationHandler { // ...略 public function sendSomethingNotification(CarbonImmutable $datetime): void { // 巨大なデータ $query = HugeSomethingModel::select('id') ->where('generated_date', '=', $datetime->format('Y-m-d')); $this->memoDebug('HugeSomethingModel::select'); $query->chunk(10000, function (Collection $records) use ($datetime) { $data = $this->getRelationData($records->pluck('id'), $datetime); $this->memoDebug('getRelationData'); $somethingContents = $this->probableSomethingRun($data); $this->memoDebug('probableSomethingRun'); $this->sendEmail($this->email, $somethingContents, $this->sqs); $this->memoDebug('sendEmail'); } } // ...略 }
この測定の結果から以下のような状況が判明しました。
- sendEmailを境にしてメモリ使用量が爆増する
- chunkのループごとに爆増したメモリ使用量はある程度は減る
- しかし前回ループと比べて100MBほどメモリ使用量が増えたままである
- ループ毎にその100MB分がぴったり増える
- 数ループ経過するとメモリリークが発生し遅くなるOR停止する
情報不足につき
これらの情報から「sendEmail内で解放しきれていない何かがあるのでは？」と推測し以下のような対応をいれてみました。
<?php class NotificationHandler { // ...略 public function sendSomethingNotification(CarbonImmutable $datetime): void { // 巨大なデータ $query = HugeSomethingModel::select('id') ->where('generated_date', '=', $datetime->format('Y-m-d')); $query->chunk(10000, function (Collection $records) use ($datetime) { $data = $this->getRelationData($records->pluck('id'), $datetime); $somethingContents = $this->probableSomethingRun($data); $this->sendEmail($this->email, $somethingContents, $this->sqs); gc_collect_cycles(); // 対応 } } // ...略 }
この対応で『sendEmailを境にしてメモリ使用量が爆増する』点で少し効果がありましたが問題に対してクリティカルヒットを出すことはできませんでした。
memory_get_usage(), memory_get_peak_usage()をソースコードに埋め込む測定方法ではシンプルである反面、そのときの全体のメモリ使用量しかわからないため、何がどれだけメモリを使用しているかまでは分かりません。
このため計測したにも関わらず原因に対して推測することしかできませんでした。
🌌メモリの深淵へ
情報不足な状況をうけて、更に一歩踏み込んでメモリの動向を探る必要がありました。
メモリプロファイラの出番です。
PHPのメモリプロファイラ事情
PHPには、いわずもがなメモリプロファイリングを行うためのツールは数多く存在します。
どれを利用するかはセットアップの都合や金銭コストの問題で選択肢が決まりそうです。
- Xdebug
- tideways_xhprof（アーカイブ済み）
- xhprof
- php-memprof
- php-meminfo
- reli-prof
- Blackfire
手軽さでいえばXdebugが最有力候補になり、デファクトスタンダードでいえばphp-memprofとなるようです。
今回は測定環境の都合と好奇心*1から『reli-prof』を利用することにしました。
reli-profを使ったプロファイリング
セットアップ
Github記載の手順通りで簡単に行うことができました。 計測に用いた環境はECSで構成されており、バッチが実行されるコンテナ内に直接インストールしました。
composer create-project reliforp/reli-prof cd reli-prof
計測
まずはバッチを起動させます。
php artisan batches:runSemothing
そしてバッチが実行されているプロセスを特定し、そのプロセスに対してreliでプロファイリングを実行します。
php ./reli i:memory -p 1234 > memory_dump.json
たったこれだけです☺️すごい。
計測結果から
出力されたmemory_dump.jsonをjqなどで加工すると次のような結果になりました。
chunkループ 1巡目
class_name count memory_usage ========== ===== ============ App\\Dummies\\DummyModelA 47170 26792560 App\\Dummies\\DummyModelB 9518 5710800 App\\Dummies\\DummyModelC 3798 2157264 App\\Dummies\\DummyModelD 3798 2096496 Closure 4255 1429680 APM\\Trace\\Span 2099 688472 Illuminate\\Support\\Collection 9522 685584 Illuminate\\Database\\Eloquent\\Collection 9520 685440 Illuminate\\Routing\\Route 889 291592 GuzzleHttp\\Psr7\\Uri 1105 185640
chunkループ 2巡目
class_name count memory_usage ========== ===== ============ App\\Dummies\\DummyModelA 47033 26714744 APM\\Trace\\Span 50257 16484296 App\\Dummies\\DummyModelB 9533 5719800 App\\Dummies\\DummyModelC 3797 2156696 App\\Dummies\\DummyModelD 3797 2095944 Closure 3310 1112160 Illuminate\\Support\\Collection 9537 686664 Illuminate\\Database\\Eloquent\\Collection 9535 686520 Illuminate\\Routing\\Route 889 291592 GuzzleHttp\\Psr7\\Uri 790 132720
上記の結果を見ると、APM\Trace\Spanというクラスがループを追うごとにメモリ使用量が増大していることが判明しました。
これを受けて対策を打つことができ、無事にバッチの実行時間を元に戻すことができ、解決に至りました。
APM\Trace\Spanのクラスを含むライブラリを数日前にバージョンアップしていた事実がありましたがバッチの処理には直接現れないため、この計測結果を見るまでは気付けませんでした。
推測・予測を裏切ってくれる計測の大切さを再確認することができた次第です。
推測するな、計測せよ
Rob Pikeさんの金言ですが計測した後にその事実から推測すること自体は間違いではないと思います。
しかしながらその計測結果の精度によっては推測できる限界があるため、もっとよい計測方法はないか？もっと詳細な計測データを取得するにはどうする？と常に自問自答し続けることが調査には大切でした。
まとめ
- 詳しいメモリの動向を探らない限りは推測の域を出ないことが多い
- 今回利用したreli-profはシンプルで強力！今後も使っていきたい
参考
XHProf www.php.net
php-memprof pecl.php.net
php-meminfo github.com
Blackfire www.blackfire.io
*1:PHPカンファレンスで登壇をみて知って以来使う機会を伺っていました。
以下はリアルタイムでみた登壇の資料ではありませんが、reli-profについて詳しくご紹介いただいている資料です。
