ロギングミドルウェアの『リクエストボディ全記録』がAPIレスポンス速度に与える影響──本番環境での測定結果

はじめに：デバッグの便利さと運用のコスト

APIの開発・運用フェーズで、リクエストボディをログに全記録するミドルウェアを導入するかどうかは、一見シンプルな判断に見えます。「デバッグが楽になるなら入れよう」という流れは自然なものです。

ただ現場では、このシンプルな選択が本番環境のレスポンス時間に静かに影響を与えることが多くあります。テスト環境では問題なく動いていても、本番の実データ量・リクエスト頻度・ログ出力の仕組みが組み合わさると、予期しない遅延が生じるケースです。

今回は、実際に複数の構成でロギングミドルウェアの影響を測定し、どの条件下で問題が顕在化するのか、そして設計判断をどう進めるべきかを整理しました。

検証の前提と測定構成

測定環境

• API基盤: Node.js（Express） + TypeScript
• ロギング層: Winston（複数トランスポート対応）
• 本番相当環境: AWS EC2（t3.medium）、メモリ2GB、CPU2コア
• テストデータ: 実運用に近い複数パターンのリクエストボディ（小～大）
• 負荷生成: Apache JMeter、同時接続数 50～200、リクエスト継続時間 10分

比較対象

以下の4パターンでレスポンス時間（p50, p95, p99）とCPU使用率を記録しました。

1. ロギングなし（ベースライン）
2. リクエストボディ全記録 → コンソール出力のみ
3. リクエストボディ全記録 → ファイル出力のみ（日次ローテーション）
4. リクエストボディ全記録 → コンソール＋ファイル出力

各パターンで、リクエストボディサイズを50KB・500KB・2MBの3段階で変動させて測定しました。

検証結果：想定外の遅延が生じた条件

1. コンソール出力の影響は軽微だが、バッファリングで変動

結果: ボディサイズ 50KB 程度なら p50 で +2～5ms、p95 で +8～15ms 程度に留まります。

ただし、以下の条件で悪化します。

• ボディサイズが 500KB を超える場合: p99 で +50ms 超過
• 同時接続数が 100 を超える場合: ストリーム書き込みのバッファが溜まり始め、p95 で +20～30ms
• ロギング層でのシリアライズ処理が重い場合（大きなオブジェクトの JSON 変換）: +30～60ms

// 典型的な実装例（改善前）
app.use((req, res, next) => {
  logger.info('Incoming request', {
    method: req.method,
    path: req.path,
    body: req.body,  // ← ここで大きなボディ全体を JSON シリアライズ
    timestamp: new Date().toISOString()
  });
  next();
});

2. ファイル出力は I/O 待機で顕著な遅延

結果: これが最も影響が大きかった点です。

• ボディサイズ 50KB: p50 +3ms、p95 +12ms
• ボディサイズ 500KB: p50 +8ms、p95 +45ms、p99 +120ms
• ボディサイズ 2MB: p50 +25ms、p95 +180ms、p99 +400ms超

ファイル I/O は、ディスク書き込みの完了を待つため、ネットワーク遅延よりも制御しやすいようで見えて、実際には OS のバッファリング戦略に左右されます。特に以下の場合に悪化します。

• EBS のバースト容量が枯渇している
• ログローテーション処理が同時実行されている
• ディスク I/O スケジューラが他のプロセスの書き込みで競合している

3. コンソール＋ファイル出力は複合効果で二重苦

結果: p95 で +60～80ms、p99 で +200ms超。単純な足し算ではなく、バッファリング層が複数になることで遅延が増幅されます。

実装の工夫：影響を最小限に抑える設計

現場では、ロギングを完全に外すのではなく、記録する範囲を制限する判断が現実的です。

1. ボディサイズを制限してログ出力

const MAX_LOG_BODY_SIZE = 1024; // 1KB までに制限

app.use((req, res, next) => {
  let logBody = req.body;
  
  if (JSON.stringify(req.body).length > MAX_LOG_BODY_SIZE) {
    logBody = {
      _truncated: true,
      size: JSON.stringify(req.body).length,
      keys: Object.keys(req.body)
    };
  }
  
  logger.info('Request received', {
    method: req.method,
    path: req.path,
    body: logBody
  });
  
  next();
});

この方法で、p95 の遅延を +10ms 前後に抑えられます。

2. 非同期・非ブロッキングログ出力

// Winston の設定例
const logger = winston.createLogger({
  transports: [
    new winston.transports.File({
      filename: 'api.log',
      level: 'info',
      maxsize: 5242880, // 5MB
      maxFiles: 5,
      tailable: true,
      // ← 重要: 非同期書き込みを明示
      handleExceptions: false
    })
  ]
});

ただし非同期化しても、ログ出力の遅延が見えなくなるだけで、実際の I/O 負荷は変わりません。CPU スレッドプール内で処理されるため、高負荷時には結局影響を受けます。

3. 開発環境と本番環境でログレベルを分ける

const logLevel = process.env.NODE_ENV === 'production' ? 'warn' : 'debug';

app.use((req, res, next) => {
  if (logLevel === 'debug') {
    logger.debug('Full request body', { body: req.body });
  } else {
    logger.info('Request received', { 
      path: req.path,
      method: req.method
      // ボディは記録しない
    });
  }
  next();
});

本番では INFO レベル以上に制限し、リクエストボディは記録しない方針が実務的です。

実務投入時の判断ポイント

どんな案件なら採用できるか

• 低頻度の API（秒間リクエスト数が 10 以下）
• 小～中規模のボディサイズ（通常 50KB 以下）
• レスポンス時間に余裕がある API（SLA が 500ms 以上）
• デバッグが頻繁に必要な初期開発フェーズ

採用を避けるべき案件

• 高頻度 API（秒間 100 リクエスト超）
• 大容量ボディを扱う API（ファイルアップロード、バッチデータ）
• レスポンス時間が厳しい仕様（SLA 100ms 程度）
• 本番環境での安定性が最優先

追加で確認すべきポイント

1. ログ保存先の I/O スループット: ローカルディスク vs NFS vs CloudWatch Logs で大きく異なります
2. ログローテーション戦略: 日次か時間単位か、その際の CPU スパイクを測定してください
3. ログ検索・分析の需要: ELK Stack や CloudWatch を使う場合、ネットワーク転送も負荷に含めて考えます
4. エラーログとの分離: 全リクエストではなく、エラー時だけ詳細ログを出力する仕組みも検討値があります

現場での判断

ロギングミドルウェアは「あると便利」ですが、本番環境ではコストと利益のバランスを明確に測る必要があります。

テスト環境で問題なく動いても、実データ量や実アクセスパターンの下では別の顔を見せます。導入前に、自分たちの API 仕様・ボディサイズ・アクセス頻度に合わせた簡易的な負荷測定をしておくことをお勧めします。

完璧なログを目指すのではなく、「本番で何が起きたときに、どの情報があれば問題解決できるか」という逆算の思考が、実務では強みになります。