app serverがリクエストの処理にかかった時間をログに記録する

Webアプリケーションのパフォーマンスをトラッキングするために、app serverの処理にかかった時間を記録したい。方法を、以下のように分類できる。 - 1. reverse proxy側で、proxy先のapp serverがレスポンスを返してくるのにかかった時間をログに記録する場合 - 1.1 ngin…

Webアプリケーションのパフォーマンスをトラッキングするために、app serverの処理にかかった時間を記録したい。

方法を、以下のように分類できる。

1. reverse proxy側で、proxy先のapp serverがレスポンスを返してくるのにかかった時間をログに記録する場合
- 1.1 nginx
- 1.2 apache
1. app serverでリクエスト処理にかかった時間を出して、ログに記録する場合
- 2.1 reverse proxyで記録する場合
- 2.2 app serverでログに記録する場合

1と2とでは出てくる数字が違うだろうけど、本件に必要なのはパフォーマンス改善を示す一貫した指標なので、どっちでもいいと思う。

1. reverse proxy側で取る場合

1.1 nginx

log_formatディレクティブに$upstream_response_timeという変数を使えるので、

log_format main  '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for" '
'"$upstream_response_time"'; # ココ

上記のような感じで足してやればよい。

ドキュメント: http://wiki.nginx.org/NginxHttpUpstreamModule#.24upstream_response_time
試してみた例: https://github.com/kentaro/nginx-response-time

As in $upstream_addr, if more than one upstream server is accessed, the values are separated by commas and colons with spaces.

HttpUpstreamModule

とあって、

f:id:antipop:20120626124218p:plain

らしいのだけど、どういう状況なのかよくわかってない。一回のリクエストに対して複数のupstreamにproxyすることがあるってこと？とかいってたら、さらに教えてもらった。typester++

f:id:antipop:20120626174431p:plain

1.2 apache

(この方法ではダメです。後述の追記参照)

CustomLogディレクティブのフォーマット文字列に以下があるので、

%D - リクエストを処理するのにかかった時間、マイクロ秒単位
%T - リクエストを扱うのにかかった時間、秒単位

ログファイル書式に適当に追加する。

ドキュメント: http://httpd.apache.org/docs/current/ja/mod/mod_log_config.html#formats

[追記]

@kentaro $upstream_response_timeはproxy先からレスポンスを受け取るまでの時間で、Apacheの%D,%Tに相当するクライアントに返しきるまでの時間は$request_timeでしょうか

— fujiwara (@fujiwara) June 25, 2012

というわけでおおいに勘違いしておりました。

nginxの$upstream_response_timeは、upstreamからレスポンスを受け取るまでの時間とのことで、Apacheの%Dや%Tとは全然違いますね……。

Apacheの件: http://dev.ariel-networks.com/Members/inoue/response-time/

というか、逆にApacheで$upstream_response_time同様の数値を取るにはどうしたらよいんだろう……。

んでもって、いずれにせよどっちも記録しておく方が「重い!!1」という時の原因切り分けに便利とのこと。

$upstream_response_timeと$request_timeは両方ログに記録しておくと、クライアント側とアプリ側どっち要因か判別しやすいのでおすすめ #nginx

— fujiwara (@fujiwara) June 25, 2012

[追々記]

とりあえずであれば mod_proxy_http.c の proxy_http_handler で計測して r->subprocess_env にいれればできるかな

— masahiro nagano (@kazeburo) June 25, 2012

そっちでどうこうするしかないのかなー。

2. app serverでリクエスト処理にかかった時間を出して、ログに記録する場合

2.1 reverse proxyで記録する場合

たとえばX-RuntimeというHTTPヘッダでレスポンスタイムを吐いているなら、apacheなら%{X-Runtime}oでログに記録。

rackアプリならRack::Runtime
PHPなら、なんか適当にがんばる(いい方法ないかな)。

2.2 app serverでログに記録する場合

app serverでログに記録する(たとえばapache + mod_php)場合、リクエストの最初と最後の時間差を取って、apache_note()で適当に付与しておき、んでもって、apacheログフォーマットの%{FOOBAR}nで、その値をログに記録しておくのがよい？