Subscribed unsubscribe Subscribe Subscribe

Kentaro Kuribayashi's blog

Software Engineering, Management, Books, and Daily Journal.

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

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

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

  • 1. reverse proxy側で、proxy先のapp serverがレスポンスを返してくるのにかかった時間をログに記録する場合
  • 2. 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"'; # ココ

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

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 - リクエストを扱うのにかかった時間、秒単位

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

[追記]

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

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

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

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

[追々記]

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

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で、その値をログに記録しておくのがよい?