【ISUCON14】NginxアクセスログのLTSV化とalp解析で「真のボトルネック」を特定する

ISUCONなどのWebアプリケーション性能改善において、最初につまずきやすいのが「ボトルネックをどう見つけるか」という課題。

推測でコードを直してもスコアは伸びない。Webサーバー（Nginx）のアクセスログをLTSV形式で出力し、ログ解析ツール alp で集計することで、システム全体で最も時間を消費しているエンドポイントをデータに基づいて特定する。

TL;DR：この記事のまとめ

要するに、NginxのアクセスログをLTSV化して alp で集計し、スロークエリログと突き合わせることで真のボトルネックを特定するまでの実践記録。

• アクセスログのLTSV化: レスポンスタイム（reqtime / apptime）をログに記録し、Dockerボリュームマウント経由でホストから解析可能にする構成。
• alpによる集計: URL正規化（-m）を行い、合計時間（Sum）と平均時間（Avg）の2軸で負荷ランキングを作成。
• ボトルネックの特定: 合計処理時間の97%を占める通知API群が、インデックス欠落によって rides と ride_statuses テーブルの全件フルスキャンを引き起こしていることを解明。

1. 背景と課題

前回のチューニングでは、MySQLのスロークエリログ（pt-query-digest）をもとに最も重かったクエリをCTE化し、複合インデックスを追加してスコアを改善した。

しかし、DB側の重い単発クエリを改善した次の段階で、「そもそもどのAPIエンドポイントが何回呼ばれ、トータルで何秒消費しているのか」というAPI全体の負荷状況が見えていない課題が残っていた。

Webアプリケーション全体のボトルネックを把握するための2軸：

1. アクセスログ解析（alp）: どのAPIが何回呼ばれ、合計何秒消費しているかを把握
2. スロークエリ解析（pt-query-digest）: どのSQLクエリが重いかを把握

この2つを突き合わせることで、修正すべきコードとテーブル定義の欠陥を一気に絞り込む。

2. NginxアクセスログのLTSV化

なぜLTSV形式にするのか

Nginxのデフォルトログ（Combined形式）には、リクエストの処理にかかった時間（レスポンスタイム）が含まれていない。また、スペース区切りではパースに時間がかかる。

LTSV（Labeled Tab-Separated Values）形式を採用し、2つの時間を記録して高速にパース可能にする。

• reqtime（$request_time）: Nginxがリクエストを受け取ってからレスポンスを返し終えるまでの全時間
• apptime（$upstream_response_time）: バックエンド（Node.js）が処理に費やした時間

Nginx設定の追加

development/nginx/conf.d/nginx.conf にLTSVフォーマットを定義し、ログ出力先を指定。

log_format ltsv "time:$time_local"
                "\thost:$remote_addr"
                "\tforwardedfor:$http_x_forwarded_for"
                "\treq:$request"
                "\tstatus:$status"
                "\tmethod:$request_method"
                "\turi:$request_uri"
                "\tsize:$body_bytes_sent"
                "\treqsize:$request_length"
                "\treqtime:$request_time"
                "\tapptime:$upstream_response_time";

server {
  listen 80 default_server;
  access_log /var/log/nginx/access_ltsv.log ltsv;

  # ...
}

Docker環境におけるログ出力の注意点

公式のNginx Dockerイメージでは、/var/log/nginx/access.log が /dev/stdout へのシンボリックリンクになっているため、そのままではファイルとして集計できない。

Docker Composeでホスト側のディレクトリ（./nginx/logs）をマウントし、コンテナ外のファイルシステムにログを直接書き込ませる構成に変更。

services:
  nginx:
    volumes:
      - ./nginx/conf.d:/etc/nginx/conf.d:ro
      - ./nginx/logs:/var/log/nginx

設定反映後、生ログを確認すると各フィールドがタブ区切りで出力されている。

3. alpによるアクセスログ解析

URI正規化（-m オプション）の重要性

アクセスログをそのまま集計すると、URLに含まれる動的パラメータ（/rides/01M18W0.../status など）によって数千行の別URLとして集計されてしまい、全体像が把握できない。

alp の -m オプションを使い、同一のエンドポイントとして正規化（集約）する。

alp ltsv \
  --file=access_ltsv.log \
  --sort=sum -r \
  -m "/api/app/rides/[0-9a-zA-Z]+/evaluation,/api/chair/rides/[0-9a-zA-Z]+/status,/api/app/rides/estimated-fare,/api/app/nearby-chairs.*,/api/owner/sales.*,/assets/.+,/images/.+"

4. 計測結果と2つのランキング比較

ベンチマークを実行し、出力されたアクセスログを alp で集計。

合計時間（Sum）順のランキング

システム全体で最も時間を消費しているエンドポイント順に並べ替えた集計結果。

分析結果

• 上位3つのエンドポイント（/api/chair/notification, /api/app/notification, /api/chair/coordinate）だけで、合計 2,505 秒（全処理時間の約97%） を占有。
• 1リクエストの平均時間は 140〜176ms 程度だが、ポーリングによって数千回発行されることでトータル負荷が肥大化。

平均時間（Avg）順のランキング

1リクエストあたりの処理が重いエンドポイント順（平均レスポンス時間順）に並べ替えた集計結果。

分析結果

• 1リクエストあたりの最遅エンドポイントは GET /api/app/nearby-chairs（平均 398ms、最大 535ms）。
• 呼出回数は43回と少ないものの、1回ごとの処理負荷が突出して高い。

5. ボトルネックの特定とコード・スキーマの検証

alpで特定した大ボス（/api/chair/notification）のソースコードを確認。

// webapp/nodejs/src/chair_handlers.ts
export const chairGetNotification = async (ctx: Context<Environment>) => {
  const chair = ctx.var.chair;

  await ctx.var.dbConn.beginTransaction();
  try {
    // ① 椅子に割り当てられた最新ライドを取得（8,000回実行）
    const [[ride]] = await ctx.var.dbConn.query(
      "SELECT * FROM rides WHERE chair_id = ? ORDER BY updated_at DESC LIMIT 1",
      [chair.id],
    );
    if (!ride) {
      return ctx.json({ retry_after_ms: 30 }, 200);
    }

    // ② 未送信のステータスを取得（8,000回実行）
    const [[yetSentRideStatus]] = await ctx.var.dbConn.query(
      "SELECT * FROM ride_statuses WHERE ride_id = ? AND chair_sent_at IS NULL ORDER BY created_at ASC LIMIT 1",
      [ride.id],
    );
    // ...

スローログとの合致とインデックスの欠落

MySQLスロークエリログ（pt-query-digest）を確認すると、上位を占めていたのは以下のクエリ。

• SELECT ride_statuses: 合計 約124秒（DB総時間の50%以上、約27,000回発行）
• SELECT rides: 合計 約25秒（約20,000回発行）

テーブル定義（1-schema.sql）を確認すると、以下の状態。

• rides テーブル: PRIMARY KEY（id）のみ存在し、chair_id にインデックスがない
• ride_statuses テーブル: PRIMARY KEY（id）のみ存在し、ride_id にインデックスがない

8,000回以上呼び出される通知ポーリングのたびに、rides テーブルと ride_statuses テーブルの全件フルスキャンが発生していたことが、システム全体の最大ボトルネックと判明。

6. まとめ：ISUCON初期調査の黄金パターン

今回の計測と分析を通じて体系化した、ボトルネック特定の一連のフロー：

1. 【全体俯瞰】: alp で「Sum（合計時間）」と「Avg / Max（平均・最大時間）」の上位APIを洗い出す。
2. 【現場特定】: 上位APIのソースコードを開き、発行されているSQLを確認する（pt-query-digest のスロークエリ上位と照合）。
3. 【インデックス確認】: テーブル定義（schema.sql）を確認し、WHERE、ORDER BY、JOIN に使われているカラムのインデックス有無をチェックする。
4. 【改善と再計測】: 必要なインデックス追加やクエリ最適化を実施し、ベンチマークで効果を検証する。

次回は、特定した rides および ride_statuses への複合インデックス追加を行い、スコアの変化を検証予定。