tl;dr
FuelPHPを用いたバッチ処理が遅いので調べて見たら、Monolog\Logger::\$processorsにログ出力内容を全て配列に保持しててメモリ食いつぶしてた
⇒保持したものを定期的に消すようにしたら解消した
というお話です
環境
- 言語:PHP5.6
- フレームワーク:FuelPHP 1.8
きっかけ
以下のような案件(処理内容は割愛)
- 対象は「DBから取得したレコードをループで回し、とある条件にヒットしたものをファイルに出力する」というPHPで作成されたバッチ
- 上記バッチが、最初はサクサク処理されるが、数分で目に見えてパフォーマンスが落ち、その後も処理速度がどんどん遅くなっていくため、このままでは大量件数を処理できない可能性がある
- 実装に簡単に目を通したところ、ループ内でDBから取得してきたデータを配列にずっと追加・保持しており、それを最後にファイル出力しているのが原因そう
- なので、適宜ファイル出力しちゃって配列にデータ保持しないようにして改善してくれ
調査経緯
1. メモリ使用量、処理速度の調査
まずは配列に溜め込んでいるところが本当にボトルネックになっているのかを確かめるため、メモリ使用量と1件ごとの処理速度をログに出力するようにした
⇒メモリ使用量は右肩上がりで増え続け、1件ごとの処理速度もどんどん遅くなっていった
2. 配列格納処理の削除
今度は配列に格納しつづけているのが本当に原因なのかを確認するため、1件ごとのデータを配列に格納・保持せず随時ファイルに出力していくよう変更して実行してみた
⇒メモリ使用量、処理速度ともにほぼ変化なし(0.1%単位ではマシなったかも?)
#FuelPHP側でメモリを解放せずに掴んだままにしている可能性がある?と疑い始める
3. メモリ使用量増加タイミングの調査
メモリ増加原因のアテが外れて、何の処理でメモリが増え続けているのかを断定する必要がでてきたので、バッチのビジネスロジックのステップごとにログを出力してメモリ増加の様子を確認
⇒なぜかメモリ使用量が倍近くまで増える
#ここでFuelPHPのログ出力周りが怪しいことに気が付く
4. FuelPHPのmonologを継承したloggerの処理内容を確認
このバッチではLTSV形式のログを出力しており、
Monolog\Logger::pushProcessor()で
出力するTLSVの項目と値を作成する関数をMonolog\Logger::\$processorsに格納していた
class Logger extends \Monolog\Logger
{
public function log($level, $message, array $context = array())
{
$this->pushProcessor(function ($record) {
$record['$ログ項目$'] = $値$;
});
return parent::log($level, $message, $context);
}
}
このMonolog\Logger::pushProcessor()で格納された関数は、この後削除されている様子がなかったため、メモリが増加していくのではないかと踏んだ
5. processorの削除
Monolog\Logger::popProcessorというメソッドで先頭1件のprocessorが削除できるようなので、ログ出力の度にそれを行うよう修正
class Logger extends \Monolog\Logger
{
public function log($level, $message, array $context = array())
{
if (!empty($this->processors)) {
$this->popProcessor();
}
$this->pushProcessor(function ($record) {
$record['$ログ項目$'] = $値$;
});
return parent::log($level, $message, $context);
}
}
⇒メモリが増加しないようになり、処理時間も経過時間によって遅くなっていく現象は起きなくなった
考察・結論
- monologのpushProcessorを使うときは、ログを大量に出すような処理は使わないようにするか、もしくは逐一popProcessorで出力済みの内容を削除しよう
- そもそもFuelPHP(というかPHP)自体、バッチ処理ではなくWebページのサーバ側の処理でリクエスト単位にプロセスが終了するプロダクトに適した言語なので、 学習コストがかからないからといって全部PHPで済まそうというのはやめた方がいいかも…
- このprocessorを溜め込まないようにする設定値などがあるか調査してみたが、有益な情報は得られず… というかそもそもログ内容溜め込んでいくことについて記載のあるページが見当たらないので、もし誰か知っていたら教えてください
以上