はじめに
ASP.NET Core で API を開発していたときの話です。
ログ出力には NLog を使っていました。
当時の自分は、
「Loggerなんて軽いし、new しても問題ないでしょ」
と思っていました。
DI（Dependency Injection）を使わず、
Controller 側でLogger を生成していたのですが、
これが 客先での障害につながることになります。
この記事では、
- 何が起きたのか
- なぜ開発中に気づけなかったのか
- 次から何をルール化したか
を、事故の教訓としてまとめます。
開発当時の前提
- ASP.NET Core Web API
- ログライブラリ：NLog
- 小〜中規模の API
- 開発環境・結合テストでは特に問題なし
Controller では、DIを使わずに Logger を扱っていました。
何が起きたか（事象）
本番相当の環境で、負荷をかけたところ次のような現象が起きました。
- プロセスのメモリ使用量が 徐々に増え続ける
- GC が走ってもメモリが元に戻らない
- 数時間〜半日程度でプロセスが不安定になる
ポイントは、
一気に増えるのではなく、じわじわ増える
という点でした。
通常操作では気づかず、
負荷がかかって初めて表に出るタイプの問題でした。
なぜ発見が遅れたか
原因が分かるまでに時間がかかった理由はシンプルです。
- 開発環境では再現しない
- 単体テスト・結合テストでは問題なし
- しばらく動かし続けないと症状が出ない
つまり、
「動いている」状態が長く続いてしまった
のが落とし穴でした。
どうやって原因に辿り着いたか
JMeter を使って、同じ API を一定の TPS で叩き続けました。
その際に見ていたのは、
レスポンスタイムやエラー率
ではなく、
プロセスのメモリ使用量の推移
です。
負荷を止めてもメモリが戻らないことから、
「これはリークっぽい」
と疑い、実装を一つずつ確認していきました。
問題の実装
簡略化すると、次のような実装でした。
public class SampleController : ControllerBase
{
private readonly Logger _logger;
public SampleController()
{
// Loggerを直接生成
_logger = /* Loggerをnew */;
}
}
- DI を使っていない
- Controller が生成されるたびに Logger が作られる
当時は、
「Loggerなんて軽いオブジェクトだろう」
と深く考えていませんでした。
なぜこれが問題になるのか
Logger は一見すると軽そうに見えます。
しかし内部では、
- バッファ
- ファイルハンドル
- 非同期キュー
- タイマー
などを持っており、
アプリケーション全体で共有される前提にて設計されています。
DI を使わずにリクエスト単位で生成すると、
- 破棄されない内部リソースが溜まる
- 高負荷時にそれが一気に効いてくる
という状況になります。
このとき取得した、プロセスのリソース使用状況が次の図です。
CPU 使用率が大きく跳ね上がっている箇所は、
JMeter から同一 API に対して、
およそ 1,000 前後のリクエストを送信しているタイミングに対応しています。
一見すると、
- 負荷をかけたので CPU が上がっている
- よくある高負荷時の挙動
のようにも見えます。
しかし注目すべきだったのは、
負荷を止めた後の挙動でした。
GC が発生し、CPU 使用率が落ち着いた後も、
プロセスのメモリ使用量が元に戻らず、
時間とともにじわじわ増え続けていることが分かります。
この挙動から、
- 一時的な高負荷による問題ではない
- GC 管理外のリソースが解放されていない可能性がある
- 実装やライフサイクル管理に原因があるのではないか
と考え、Logger 周りの実装を重点的に見直すことにしました。
修正後の実装
修正はシンプルでした。
public class SampleController : ControllerBase
{
private readonly ILogger<SampleController> _logger;
public SampleController(ILogger<SampleController> logger)
{
_logger = logger;
}
}
- Logger の生成は DI に任せる
- Controller は「使うだけ」
- 設定はアプリ起動時に一度だけ
これで、負荷試験時のメモリ増加は解消しました。
この事故から学んだこと（ルール化）
この件以降、次のようなルールを決めました。
- Controller / Service で new しない
- Logger / HttpClient / DbContext は必ず DI 経由
- 負荷試験では「最大値」ではなくメモリが増え続けないかを見る
- 「軽そうなオブジェクトほど疑う」
特に、
DI は便利だから使うのではなく、
ライフサイクルを守るために使う
という意識に変わりました。
おわりに
今回は Logger でしたが、
同じことは他のオブジェクトでも起き得ます。
- 動いているから正しいとは限らない
- 問題は、負荷がかかってから表に出ることもある
「Loggerくらい new でいいでしょ」という油断が、
客先障害につながったという教訓でした。