WebSurfer's Home

トップ > Blog 1   |   Login
Filter by APML

IIS ログの time-taken

by WebSurfer 1. July 2016 14:39

IIS のログの中に time-taken という項目があります。具体的にいつからいつまでの時間かについて調べたのですが、その過程でいくつか発見があったので備忘録として書いておきます。(そもそもの話は MSDN Forum のスレッド「IIS 8.5のログの"time-taken"の値について」が発端です)

リクエスト処理の流れ

上の図は IIS7 がブラウザから要求を受けて応答を返すまでの流れを示しています。この図で time-taken はいつからいつまでになるかを簡単に書くと、上の図の ② で HTTP.sys が要求の最初のバイトを受け取ってから、⑨ で要求に対する最後の応答を返すまでとなります。

それに加えて、IIS6 からは最後のパケットに対するクライアントからの ACK を受け取るまでが time-taken に含まれるようになったとのことです。

詳しくは以下の Microsoft Support KB944884 の記事を見てください。

Description of the time-taken field in IIS 6.0 and IIS 7.0 HTTP logging

タイトルが "IIS 6.0 and IIS 7.0" となっていますが、IIS7.5 以降も同じだと思います。また、また例外の "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 以降では上に紹介した KB944884 の記事に書いてあるように 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月にこのブログを立ち上げました。その後 ブログ2 を追加し、ここは ASP.NET 関係のトピックス、ブログ2はそれ以外のトピックスに分けました。

Calendar

<<  October 2021  >>
MoTuWeThFrSaSu
27282930123
45678910
11121314151617
18192021222324
25262728293031
1234567

View posts in large calendar