IIS のログの中に time-taken という項目があります。具体的にいつからいつまでの時間かについて調べたのですが、その過程でいくつか発見があったので書いておきます。
(出典: Microsoft 公式解説書 一目でわかる IIS 7.0)
上の図は IIS がブラウザから要求を受けて応答を返すまでの流れを示しています。この図で time-taken はいつからいつまでになるかを簡単に書くと、上の図の ② で HTTP.sys が要求の最初のバイトを受け取ってから、⑨ で要求に対する最後の応答を返すまでとなります。
それに加えて、IIS6 以降では、最後のパケットに対するクライアントからの ACK を受け取るまでが time-taken に含まれるようになったとのことです。
詳しくは以下の Microsoft の記事を見てください。
Description of the time-taken field in IIS 7.0 HTTP logging
上の記事のタイトルは "IIS 7.0" となっていますが、IIS7.5 以降も同じだと思います。記事の Note に書いてある "TCP buffering is used" は ASP.NET Web アプリには関係なさそうです(公式文書などで裏は取れていませんが、この記事の下の方に書いた報告などからも ASP.NET でバッファを有効にしているとは考えにくいです)。
Microsoft の別の記事、例えば、Default Log File Settings for Web Sites とか W3C Logging に "Time taken does not reflect time across the network" と書いてあるものもありますが、古い記述のままで修正がされてないものと思われます。
というわけで、分かったことを箇条書きにすると以下の通りです:
-
time-taken は上の図で ② から ⑨ までの時間。
-
通常、一番最初の要求を受けてワーカープロセスを起動・初期化しログファイルを開くという操作が行われる。なので、一番最初の要求では time-taken はその分長くなる。
-
IIS6 以降では上に紹介した Microsoft の記事に書いてあるように network time も time-taken に含まれる。それゆえ、サイズの大きなファイルを遅いネットワークでダウンロードしたりすると time-taken の値は予想よりかなり大きくなることがある。
-
トレース情報で調べられる時間やプログラムで Stopwatch などを使って調べられる時間は上の図の ⑦ から ⑧ までの範囲内なので、当然 time-Taken の方が長くなる。
上記 3 すなわち「network time も time-taken に含まれる」を裏付けるような、time-taken の値が executionTimeout を越えているとか、プログラムのコードで実際に計った時間よりはるかに長いという報告が stackoverflow にありましたので、参考にリンクを張っておきます。
In our IIS logs, why do requests last 5 min and longer when executionTimeout is 110 seconds?