30

パフォーマンスの問題があるサーバーで IIS 7.5 の W3C 形式のログ ファイルをしばらく調べていましたが、MSDN のドキュメントとは対照的に、「時間」フィールドはそうではないようです。

「要求が発生した協定世界時 (UTC) の時刻」

...というよりは、応答の送信が終了した時間です。

私がこれを言うのは、ある程度制御された環境でユーザーからの一連のページ要求を追跡する場合、ユーザーは次の要求を送信するために時間をさかのぼる必要があるためです。時間のかかるエントリが多いページ。

例（セキュリティと明確さのために、編集、省略、省略しています）：

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip sc-status sc-substatus sc-win32-status time-taken
2012-11-28 22:25:17 192.168.0.21 GET /Main.aspx - 80 AWalker 192.168.0.100 200 0 0 764
2012-11-28 22:25:26 192.168.0.21 POST /Main.aspx - 80 AWalker 192.168.0.100 200 0 0 109
2012-11-28 22:25:56 192.168.0.21 GET /_Start.aspx - 80 AWalker 192.168.0.100 302 0 0 28782
2012-11-28 22:26:33 192.168.0.21 GET /Action.aspx - 80 AWalker 192.168.0.100 200 0 0 38032
2012-11-28 22:26:46 192.168.0.21 POST /Action.aspx - 80 AWalker 192.168.0.100 200 0 0 124
2012-11-28 22:27:39 192.168.0.21 GET /Information.aspx - 80 AWalker 192.168.0.100 200 0 0 52509
2012-11-28 22:27:52 192.168.0.21 POST /Information.aspx - 80 AWalker 192.168.0.100 200 0 0 140

「時間」を「リクエストを受信した」（開始または終了のいずれか、ただし応答が開始する前）と解釈すると、これは間違っているように見えます。これが私が意味することです：

  • 22:25:17 に、/Main.aspx の GET が受信され、応答の配信に 764 ミリ秒かかりました。つまり、応答は 14:25:17.764 まで終了しませんでした。
  • 14:25:26 に、/Main.aspx の POST が受信されました。前回の応答が終了してから 8 秒後です。この応答を配信するのに 109 ミリ秒かかり、14:25:26.109 で終了しました。
  • 14:25:56 に、/_Start.aspx の GET が受信されました。前回の応答が終了してから約 30 秒後です。これは適切なようです。ユーザーは、_Start.aspx へのリンクをクリックする前に Main.aspx を調べた可能性があります。奇妙なことに、この 302 Redirect 応答を配信するのに 29 秒近くかかり (28782ms)、14:26:24.782 で終了しました。しかし、それが理由を見つけるためにログを見ている理由です。
  • 14:26:33 に、/Action.aspx の GET が受信されました。前回の応答が終了してから約 8 秒後です。それは適切なようです (8 秒のユーザー応答時間)。応答には 38032 ミリ秒かかり (長すぎるため調査)、14:27:11.032 に終了しました。
  • 14:26:46 に、/Action.aspx の POST が受信されました。これは、前の応答が終了する8.2 秒前です。はい、ユーザーがリンクをクリックして次のページを表示したり、[更新] を押したりする前に、ページが完全にレンダリングされるのを待つ必要があるとは限らないことは十分承知していますが、これは非常に短いリクエストであっても頻繁に発生します。応答には 124 ミリ秒かかり、14:26:46.124 で終了しました。
  • 14:27:39 に、/Information.aspx の GET が受信されました。これは、前の応答が終了してから 52.9 秒です。テスターはシステムをできるだけ強く叩くように言われたので、少し長いように見えますが、不当に長いわけではありません。応答には 52509 ミリ秒 (ほぼ正確に 52.9 秒!) かかり、14:28:31.509 で終了しました。時間フィールドを「リクエストを受信した」と解釈すると、これは非常に奇妙な偶然の一致です。
  • 14:27:52 に、/Information.aspx の POST が受信されました。これは、前の応答が終了する39.5 秒前です。

この種のパターンは、ログで何度も繰り返されます。

逆に、「時間」フィールドを「応答終了」を意味すると解釈すると、より適切な数値が得られます。

  • 14:25:16.236 頃 (14:25:17 の 764 ミリ秒前) に、/Main.aspx の GET が受信され、配信に 764 ミリ秒かかり、14:25:17 に応答が終了しました。
  • 14:25:25.891 頃に、/Main.aspx の POST が受信されました。前回の応答が終了してから約 8.9 秒後です。この応答を配信するのに 109 ミリ秒かかり、14:25:26 に終了しました。
  • 14:25:27.218 頃に、/_Start.aspx の GET が受信されました。これは、前の応答が終了してから 1.2 秒です。これは、ユーザーの応答としては高速ですが、よく知られたメニューをナビゲートするこれらの十分に訓練されたテスターに​​とっては、それほど速くはありません。応答には 28,782 ミリ秒かかり (長すぎますが、これがパフォーマンス分析の原因です)、14:25:56 に終了しました。
  • 14:25:54.968 頃に、/Action.aspx の GET が受信されました。前回の応答が終了するまで約1.0 秒です。時間フィールドはミリ秒をキャプチャしないため、丸め誤差である可能性があります。応答には 38032 ミリ秒かかり、14:26:33 に終了しました。
  • 14:26:45.876 頃に、/Action.aspx の POST が受信されました。前回の応答が終了してから約 12.9 秒後です。これは、ユーザーの応答時間としてはごく普通のことです。応答には 124 ミリ秒かかり、14:26:46 に終了しました。
  • 14:26:46.491 頃に、/Information.aspx の GET が受信されました。これは、前回の応答が終了してから約 0.5 秒後のことです。それは、スクリプトによって開始されたリダイレクトまたは高速ユーザーである可能性があります。応答には 52509 ミリ秒かかり、14:27:39 に終了しました。遅いページ。
  • 14:27:51.860 頃に、/Information.aspx の POST が受信されました。これは、前の応答が終了してから約 12.9 秒後でした。通常のユーザー応答時間 (偶然にも以前の POST と同じ)。応答には 140 ミリ秒かかり、14:27:52 に終了しました。

「時間」フィールドがリクエストの開始ではなく、応答の終了を表すことが私にとってより理にかなっているもう1つの理由は次のとおりです。

ログエントリは物理的に「時間」フィールドの昇順 (時系列順) に記録されますが、応答が最終的に配信された後にのみ知ることができる「所要時間」フィールドが常に含まれます。

では、どの方法でしょうか？ドキュメントは間違っていますか？

4

1 に答える 1