nginxのアクセスログにレスポンスタイムを出力しておくと、パフォーマンスチューニングの観点でいろいろ役立ちそうと感じたため手順をまとめておきます。
デフォルトのアクセスログ
nginxのアクセスログはnginx.confで定義します。nginx.confで何を指定しなかった場合は以下の形式でログが出力されます。(combinedと呼ばれる形式)
log_format combined '$remote_addr - $remote_user [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent"';
各変数の内容は以下の通りです。
| 変数 | 内容 |
|---|---|
| $remote_addr | リクエストの送信元IPアドレス |
| $remote_user | ユーザー名(ベーシック認証時等に使われる) |
| $time_local | リクエストの処理完了時刻 |
| $request | リクエストのHTTPメソッド、パス、HTTPのバージョン |
| $status | レスポンスのHTTPステータスコード |
| $body_bytes_sent | レスポンスのボディのバイト数 |
| $http_referer | リクエストのReferer(遷移元)の内容 |
| $http_user_agent | リクエストのUser-Agentの内容 |
アクセスログで利用できるその他の変数
デフォルト以外にも様々な変数が利用できます。
パフォーマンスの測定やボトルネックの特定に役立ちそうな変数としては以下が挙げられます。
| 変数 | 内容 |
|---|---|
| $request_method | リクエストのHTTPメソッド |
| $request_uri | リクエストのURI |
| $request_time | リクエスト処理に要した時間 |
| $upstream_request_time | nginxがリバースプロキシとして動作する場合に、プロキシ先からレスポンスを取得するまでの時間 |
設定例
上記の変数を加えた設定例が以下の通りです。
デフォルトの出力形式では集計ツール等で扱いづらいため、json形式で出力するようにしています。
時刻(time)も見やすいように$time_iso8601に変更しています。
log_format json escape=json '{'
'"time":"$time_iso8601",'
'"host":"$remote_addr",'
'"method":"$request_method",'
'"uri":"$request_uri",'
'"status":"$status",'
'"body_bytes":"$body_bytes_sent",'
'"referer":"$http_referer",'
'"ua":"$http_user_agent",'
'"request_time":"$request_time",'
'"respons_time":"$upstream_response_time"'
'}';
$request_timeと$upstream_request_timeの違い
$request_timeはnginxがクライアントからリクエストを受けてからレスポンスを返し終えるまでの時間であるのに対し、$upstream_request_timeはnginxがプロキシ先(アプリケーションサーバー等)にリクエストを投げてからレスポンスが返ってくるまでの時間を表します。
つまり、$request_time > $upstream_request_timeの関係になります。
クライアントの回線状況に問題がない場合はこの2つの指標はほぼ同じ値になりますが、もしクライアントが線の細い回線を使っている等、通信状況がよろしくない場合は2つの指標の値が大きく乖離することになります。
このように、ネットワークがボトルネックとなっていることに気づくきっかけにもなるため、これらの2つの指標は共に出力することをお勧めします。