WebSurfer's Home

Filter by APML

IIS ログの time-taken

by WebSurfer 1. July 2016 14:39

IIS のログの中に time-taken という項目があります。具体的にいつからいつまでの時間かについて調べたのですが、その過程でいくつか発見があったので備忘録として書いておきます。(そもそもの話は MSDN Forum のスレッド「IIS 8.5のログの"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 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" と書いてあるものもありますが、古い記述のままで修正がされてないものと思われます。

というわけで、今回分かったことを箇条書きにすると以下の通りです:

  1. time-taken は上の図で ② から ⑨ までの時間。
  2. 通常、一番最初の要求を受けてワーカープロセスを起動・初期化しログファイルを開くという操作が行われる。なので、一番最初の要求では time-taken はその分長くなる。
  3. IIS6 以降では上に紹介した Microsoft の記事に書いてあるように network time も time-taken に含まれる。それゆえ、サイズの大きなファイルを遅いネットワークでダウンロードしたりすると time-taken の値は予想よりかなり大きくなることがある。
  4. トレース情報で調べられる時間やプログラムで 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?

Difference in time-taken in IIS and ASP.NET

Tags: , ,

Windows Server

About this blog

2010年5月にこのブログを立ち上げました。主に ASP.NET Web アプリ関係の記事です。ブログ2はそれ以外の日々の出来事などのトピックスになっています。

Calendar

<<  November 2025  >>
MoTuWeThFrSaSu
272829303112
3456789
10111213141516
17181920212223
24252627282930
1234567

View posts in large calendar