IIS

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 マニュアル

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

これだけ。

運用系でやってしまった。監視システムから障害報告が上がってきて驚いた。

IIS6 に接続できない。「サーバが見つかりません」エラーになる。IIS を再起動してもダメ。サーバにパケットをドロップされてるような挙動だ。

イベントログには怪しげなエラーがあった。
でも原因不明。machine.config に変なエントリがあったりするとか? netstat -a したら ポート80と443で IIS が LISTEN してるから、待ち受けはできてるはずなんだけど。リクエストをハンドリングするエンジンあたりがおかしいのかな?

イベントの種類:    エラー
イベント ソース:    W3SVC
イベント カテゴリ:    なし
イベント ID:    1004
日付:        2005/08/31
時刻:        10:33:00
ユーザー:        N/A
コンピュータ:    SERVER0
説明:
サイト '1' の URL プレフィックス 'https://*:443/Exchange/' を登録できません。サイトは非アクティブにされています。データ フィールドにはエラー番号が含まれています。

詳細な情報は、http://go.microsoft.com/fwlink/events.asp の [ヘルプとサポート センター] を参照してください。
データ:
0000: 94 04 07 80              []..[]

Google で URL プレフィックス 登録できませんを検索しても情報なし。イベント ID 1007 については MS の情報があったけど、本件には関係ないし。

ちなみに http://go.microsoft.com/fwlink/events.asp にアクセスしたら、「(エラーの) 情報を送信してよろしいですか?」と聞かれ、いいえにするとサポートセンターの閲覧さえできなかった。仕方がないので「はい」を選んだら、「情報はありません」という趣旨の表示。なんだそれ。

- OS 再起動で直った

OS を再起動したら直った。とりあえず OS 再起動って、なんだか昔の Windows っぽい対処法だなあ。私が仕事場で使ってる WindowsXP SP2 マシン FMV E600 も二日に一度くらいはフリーズしてるから、「昔の Windows」でもないか。ブルースクリーンとかじゃなくて、キーボードもマウスも反応しなくなるってパターン。何かのドライバかウイルス対策ソフトが悪いのかな。

Web サービスにリクエストを投げたときに、それがタイムアウトするまでの時間を延ばしたい。

- 大人の事情

Web サービスのタイムアウトの時間を延ばすなんて、なんでそんなことする必要があるの? と思うかもしれない。でも、大人にはいろいろ事情がある。とにかく Web サービスがタイムアウトすることだけは避けなければならない。それが今回の課題。たとえクライアントからリクエストを投げた後、レスポンスが返ってくるまで2分とかかかったとしても。

- Web サービスの背後で動いてるもの

Web サービスは単純だ。SOAP なり REST なりでリクエストを投げ、レスポンスが返ってくる。ただそれだけ。でも、普通はこれを実現するためにいくつかのミドルウェアが背後で動いている。

データストアとして、データベース。たとえば、MS SQL Server。
データベースに接続しクエリを投げるためのデータプロバイダ。.NET で MS SQL Server 相手だったら System.Data.SqlClient。
データストアから取得したデータを加工するビジネスロジック。
ビジネスロジックを載せるための Web アプリケーションフレームワーク。たとえば、ASP.NET。
REST や SOAP のリクエストを受けるための HTTP サーバ。たとえば、IIS (Internet Infomation Server)。
REST や SOAP のリクエストを投げるための HTTP クライアント。.NET だったら System.Web.Services.Protocols.SoapHttpClientProtocol あたりがいろいろやってくれる。

これらの全てのタイムアウトを延ばさないと、Web サービスのタイムアウトを延ばすという目標は達成できない。以下、それぞれのタイムアウト設定方法のメモ。

- SQL Server のクエリ実行時間タイムアウト

SqlCommand.CommandTimeout プロパティ System.Data.SqlClient 名前空間
http://www.microsoft.com/japan/msdn/library/ja/cpref/html/fr ...

プロパティ値
コマンド実行の待機時間 (秒)。既定値は 30 秒です。

解説
0 は、制限なしを示します。ただし、コマンド実行の試行が永久的に待機されるため、 CommandTimeout では使用しないでください。

今回設定が必要なもののうち、この SqlCommand.CommandTimeout が一番短い。短いといっても、30秒もあるわけだけど。

- IIS の HTTP レスポンス生成時のタイムアウト

IIS5 の場合。インターネット サービス マネージャを開き、Web サイトのプロパティを表示させる。「既定の Web サイト」しかなかったら、それを右クリックしてプロパティを表示させる。「Web サイト」タブの「接続」の「接続のタイムアウト」に秒単位で設定できる。デフォルトは900秒。

接続のタイムアウトを設定する
http://www.microsoft.com/resources/documentation/windowsserv ...

- SOAP クライアントのタイムアウト

WebClientProtocol.Timeout プロパティ
http://www.microsoft.com/japan/msdn/library/ja/cpref/html/fr ...

プロパティ値
XML Web サービスを同期的に呼び出すときのタイムアウト (ミリ秒単位)。既定値は 100000 ミリ秒です。

解説
Timeout プロパティを Timeout.Infinite に設定すると、要求がタイムアウトしないことを示します。XML Web サービス クライアントが Timeout プロパティをタイムアウトなしに設定しても、Web サーバーが要求をサーバー側でタイムアウトにする場合があります。