HTTP リクエストの処理完了までの所要時間をログに記録する

http リクエストの処理にかかった時間をロギングする方法のメモ。

集計や分析、パフォーマンス劣化の監視などで活用するため、http サーバ側でリクエストを処理したあとレスポンスを返すまでどれだけ時間がかかったかを記録したい。

所要時間などの値は http サーバ上で動くアプリケーション側でロギングする仕組みを作るのが普通。ただ、とりあえず記録さえできればいいときは、http サーバが提供するロギング機能を使ってアクセスログに書かせるのが手っ取り早い。

- Apache 2系

LogFormat ディレクティブ、CustomLog ディレクティブの書式指定文字列で %D を使う。

mod_log_config - Apache HTTP サーバ
http://httpd.apache.org/docs/2.2/ja/mod/mod_log_config.html# ...

%D リクエストを処理するのにかかった時間、ミリ秒単位

- Apache 1.3系

標準では出力できない? モジュールなどが必要? 今回は Apache 1.3系は調査対象外なので詳細は調べていない。%T で秒単位ながらもロギングできるらしいが未確認。もっとも、秒単位だとあまりうれしくない。何もないよりはいいけど。

- Internet Information Service (IIS) 6.0

インターネット インフォメーション サービス (IIS) マネージャ の「Web サイトのプロパティ」の「Web サイト」タブの「ログの記録を有効にする」の「詳細設定」タブの「所要時間 ( time-taken )」チェックボックスをオンにする。

Internet Information Service (IIS) 6.0 ヘルプ

[所要時間]

処理が完了するまでに要した時間を記録するときに選択します。ODBC ログを除くすべてのログ形式では、次の手順に従い、所要時間がミリ秒単位でログが記録されます。HTTP.sys (カーネルモード ドライバ) が、要求の解析を開始する前に最初のバイトを受信すると、クライアント要求のタイムスタンプが初期化されます。IIS で最後の送信が完了すると、クライアント要求のタイムスタンプが停止します。ネットワーク上での時間は所要時間に反映されません。また、サイトへの最初の要求は、他の類似した要求、または同一の要求に比べて、所要時間がわずかに長くなります。これは、HTTP.sys により最初の要求時にログ ファイルが開かれるからです。

以下は出力されるログのサンプル。

#Fields: date time s-sitename s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs-version cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken
2005-12-27 09:14:59 W3SVC1 127.0.0.1 GET /iisstart.htm - 80 - 127.0.0.1 HTTP/1.1 Mozilla/4.0+(compatible;+MSIE+6.0;+Windows+NT+5.2;+SV1;+.NET+CLR+1.1.4322) - 200 0 0 1842 251 40

末尾の 40 が time-taken の値。単位はミリ秒。

- Internet Information Service (IIS) 5.0

IIS 5 でも IIS 6 と同じ手順で設定可能。ただ、マニュアルの記述が非常に少ない。

IIS 5.0 マニュアル

[所要時間]  アクションに要した時間。

これだけ。