nginx: request_time が速いのに遅い？ $upstream をログに出してリトライと内訳を見る

どんなときに使う？

• 「平均や全体の p99 は速いのに、特定の操作だけ遅いと言われる」
• upstream（アプリサーバー）側でタイムアウト → nginx が次の upstream に再送していて、実は 1 リクエストで 2 回処理されている、のを見つけたい

やり方

1. ログに upstream 情報を足す

log_format timing '$remote_addr [$time_local] "$request" $status '
                  'rt=$request_time '
                  'uaddr="$upstream_addr" ustatus="$upstream_status" '
                  'urt="$upstream_response_time" uct="$upstream_connect_time" '
                  'uht="$upstream_header_time"';
access_log /var/log/nginx/access_timing.log timing;

nginx の仕様では、リクエスト処理中に複数の upstream に問い合わせた場合、$upstream_addr / $upstream_status / $upstream_response_time などはサーバーごとの値がカンマ区切りで並ぶ（例: urt="3.002, 0.015"）。値が複数あるログ行が「リトライが起きたリクエスト」。

2. パーセンタイルは「リクエストの種類ごと」に

• $request 単位で集計する。ただし /users/123 と /users/456、?page=2 のように パスやクエリ文字列に入る可変部分は先に共通化（/users/:id など）してからまとめる。
• 全体のパーセンタイルだと、軽いリクエストが大量にあるせいで遅いエンドポイントが埋もれる。

注意点

• 変数の意味や区切り文字（カンマとコロン）の詳細は nginx の ngx_http_upstream_module のドキュメントで確認する。
• ログ集計には alp などの既存ツールも使える（パスの正規化オプションがある）。

出典

• @matsuu · 2026-10-04 （記事「nginxのrequest_timeは速いのに遅い理由」へのコメント）