WebSurfer's Home

トップ > Blog 1   |   ログイン
APMLフィルター

IIS ログの time-taken

by WebSurfer 2016年7月1日 14:39

IIS のログの中に 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

WCF と executionTimeout

by WebSurfer 2016年6月18日 13:23

ASP.NET でホストされていても、WCF サービスを要求した場合は httpRuntime 要素の executionTimeout 属性の設定は効かない(タイムアウトしない)という話を書きます。

元は MSDN Forum の「webconfig 内の executionTimeout 値が有効にならない」という表題のスレッドでの話です。

MSDN Forum での話では、非同期ではないのかとか ASP.NET 互換モードの設定がされてないのではとかいろいろ紆余曲折ありましたが、結局一番の原因は:

ASP.NET でホストされていても、.NET 3.0 SP1 以降 WCF サービスを要求した場合は executionTimeout が Int32.MaxValue に設定される

・・・ということだと分かりました。

ググって見つけた記事「All WCF timeouts explained」にそれが書いてありました。記事の一番下に "Nowadays (.NET 3.0 SP1 and later) there is no more to say. The ExecutionTimeout is set to int.MaxValue for WCF requests. Thereby WCF is granted full control over its own request lifetimes." という記述があります。

上記の記事を裏付ける Microsoft の公式文書は見つかっていませんが、実際に検証してタイムアウトしないことやHttpServerUtility.ScriptTimeout プロパティ設定値を調べた結果から、間違いないようです。

MSDN Blog の記事(例えば「Timeouts in WCF and their default values」)などによると、WCF サービスでも ASP.NET でホストされていれば executionTimeout 属性の設定は有効というようなことが書いてあって惑わされましたが、それは .NET 3.0 SP1 適用前の話だったようです。

主な話は以上ですが、これを調べる過程でタイムアウトや WCF に関することがいろいろわかったので、忘れないように以下にまとめて書いておきます。

  1. WCF サービスでは executionTimeout 属性の設定は効かない
    WCF サービスを要求した場合は executionTimeout が Int32.MaxValue に設定されます。ScriptTimeout プロパティの値で確認すると、compilation debug="false" / "true" の設定に関わらず Int32.MaxValue 即ち 2147483647 になることが確認できます。
  2. タイムアウトのチェックは 15 秒毎
    MSDN Blog の記事「How the Execution Timeout is managed in ASP.NET」によると、タイムアウトは System.Threading.Timer によって 15 秒毎に発生するイベントでチェックしているとのことです。従って、普通の .aspx ページなど executionTimeout が有効な場合でも、設定された時間で正確にタイムアウトすることはないです。
  3. 非同期ではタイムアウトさせられない
    ASP.NET の非同期というのは MSDN の記事「ASP.NET の非同期/待機の概要」に書いてあることですが、その記事の図3にあるように、「外部リソースを非同期に待機中」はスレッドプールにスレッドが戻されます。一方、上記 2 で紹介した MSDN Blog の記事に書かれていますように、タイムアウトはスレッドを Abort することで行われるそうです。ということは、非同期の場合はタイムアウトさせるスレッドが存在しない(=タイムアウトさせられない)ということになります。.NET 4.5 では async / await が使えるようになって、Visual Studio でコードを生成する際に自動的に非同期になるようですが、その場合は executionTimeout が有効にならないと思います。(未検証です)
  4. WCF サービスには非同期 HTTP ハンドラを利用できる
    MSDN Blog の記事「Orcas SP1 Improvement: Asynchronous WCF HTTP Module/Handler for IIS7 for Better Server Scalability」によると、.NET 3.5 SP1 から非同期版ハンドラが利用できるようになったそうです。自分の開発マシン (Vista SP2 32-bit, IIS7) を調べてみると、記事に書いてある通りの同期版・非同期版両方のハンドラが存在してました。記事によるとデフォルトでは同期版を使うそうです。しかし、自分の環境でHttpContext.Handler プロパティを使って調べた限りでは非同期版が使われていました。MSDN Blog の記事と矛盾する理由は不明です。
  5. debag="true" の場合の executionTimeout
    MSDN ライブラリの executionTimeout 属性の説明には "このタイムアウトは、compilation 要素のデバッグ属性が False の場合だけ適用されます" と書いてありますが、普通の .aspx ページを呼び出したとき compilation debug="true" では、ScriptTimeout プロパティの値で確認すると 30000000 になります。(WCF サービスを呼び出したときは、debug="false" / "true" に関わらず、ScriptTimeout プロパティの値は Int32.MaxValue 即ち 2147483647 になります)

Tags: ,

ASP.NET

ダウンロードの際の拡張子

by WebSurfer 2016年6月12日 15:27

以下は Internet Exploler (IE) に限った話ですのでご注意ください。

IE でファイルをダウンロードする際、応答ヘッダに Content-Type のみが指定されていて、Content-Disposition が指定されてない場合、ファイルの拡張子はどうなるかという話を書きます。

レジストリでの拡張子設定

簡単に言うと、Microsoft の Support の記事「ファイルのダウンロードダイアログで表示されるファイル名の命名規則」の「詳細」のセクションの 2 に書いてありますように、レジストリの HKEY_CLASS_ROOT\MIME\Database\Content Type の設定によります。

具体例を書くと以下の通りです。

上の画像はレジストリの Content Type が image/tiff の拡張子の設定です。自分の開発マシン(Vista SP2 32-bit)ではデフォルトで Extension のデータは .tif になっていました。

開発マシンのローカル IIS7 に設定した images フォルダに、内容は全く同じで拡張子のみ .tiff と .tif と異なる 2 つの tiff 画像ファイルを作り、以下のように a 要素で直リンクします。それをブラウザに表示してリンクをクリックするとどうなるでしょうか?

<a href="/images/tiffdocument.tiff">tiffdocument.tiff</a>

<a href="/images/tiffdocument.tif">tiffdocument.tif</a>

実際に 2 つのファイルの拡張子は .tiff / .tif と異なるのですが、IIS7 がそれらの画像を取得してダウンロードする際、応答ヘッダに含まれる Content-Type はいずれの場合も image/tiff と設定します。(注:image/tif では IE が認識できません)

Content Type: image/tiff を受信した IE のあるクライアント PC のレジストリ設定は、上の画像が示すように image/tiff の Extension のデータが .tif となっているので、ダウンロードされた画像ファイルの名前.拡張子はどちらのリンクも tiffdocument.tif になります。

ちなみに、上の画像のレジストリの Extension のデータ .tif を .tiff に変更すると、ダウンロードされたファイルの拡張子は .tiff になります。

ダウンロードされたファイルのファイル名.拡張子を実際のファイルの通りにするには、サーバー側で Content-Disposition ヘッダでファイル名.拡張子をきちんと指定すれば、IE の場合は指定したとおりになります。

ただし、先の記事「ダウンロードの際の拡張子 と MIME Type の指定」に書きましたように、Content-Type の方を優先するブラウザもあります。

なので、ダウンロードするための HTTP ハンドラ等を作る際は、Content-Type と Content-Disposition の両方を正しく設定するように注意した方がよさそうです。

なお、プログラムで Content-Type を設定する際は image/tif ではなくて image/tiff としないと IE は認識しませんので注意してください。image/jpg も同様にダメで image/jpeg としないと IE は認識しません。

Tags: ,

Upload Download

About this blog

2010年5月にこのブログを立ち上げました。その後 ブログ2 を追加し、ここは ASP.NET 関係のトピックス、ブログ2はそれ以外のトピックスに分けました。

Calendar

<<  2017年2月  >>
2930311234
567891011
12131415161718
19202122232425
2627281234
567891011

View posts in large calendar