IIS 10.0でリクエストを受信してからASP.NETアプリケーション(ワーカースレッド)にデータを渡すまでの間、どこで時間がかかっているかを調べる方法はありますか

20927774 85 評価のポイント
2024-11-04T22:17:13.76+00:00

.NET COREのASPアプリケーションをIISで動かしていますが、時々処理が遅い時があると利用者より問合せがありました。(正確な数値ではありませんが、およそ3割くらい)

IISのアクセスログを見ると、time-takenの値が通常より大きな値となっていることを確認しています。(通常は数百msのところ、1500~2500msになっている)

ワーカースレッド上で動いているアプリケーションの、処理開始時と終了時の時刻を確認すると、通常の処理時間より若干遅いが、数百msで処理が完了していることを確認しました。

そこで、wiresharkを使って該当リクエストのパケットをキャプチャしました。

時刻をまとめると以下の通りです。

<wireshark上>

13:32:53.944681 クライアントからAppplication Data受信 ・・・(1)

13:32:53.990625 サーバからクライアントに↑のACKを返送 ・・・(2)

13:32:55.648088 サーバからクライアントにApplication Data返送 ・・・(3)

・・・

<ASP.NETアプリケーション上のログ>

13:32:55 処理開始

13:32:55 処理終了

処理時間 975ms

<IISアクセスログ上のtime-takenの値>

time 13:32:55

time-taken 1771

※IISのアクセスログに記録されている時刻はリクエストを受けた時間ではなく、リクエストをクライアントに返送後、クライアントからその返送に対するACKを受け取った時刻が記録されています。

IISのアクセスログのtime-takenの値1771msから、アプリケーションでかかった処理時間975msを引くと、796msとなりますので、これがIISの内部でかかっている処理時間と推測されます。

また、wiresharkのログ(3)とASP.NETアプリケーションの処理開始時間が同じ13:32:55台なのでアプリケーションが処理終了後はすぐにクライアントにデータ返送しているものと推測されます。

今回、知りたいのは、wiresharkの(2)と(3)の間のアプリケーションに処理が渡るまでにどこで時間がかかっているかということです。

IISにデバッグを入れて、IISの内部処理のどこで時間がかかているのか調べる方法はございますでしょうか。

なお、該当時間帯にアプリケーションプールのリサイクルが発生していなかったことは、OSのアプリケーションログにログが出ていないことで確認しています。(リサイクルが走ると、当ログにワーカースレッドのstartとshutdownのログがでてきます。)

インターネット インフォメーション サービス
ASP.NET
ASP.NET
Web アプリケーションと XML Web サービスを構築するための Microsoft .NET Framework のテクノロジのセット。
7 件の質問
Windows Server
Windows Server
エンタープライズ レベルの管理、データ ストレージ、アプリケーション、通信をサポートする Microsoft サーバー オペレーティング システムのファミリ。
60 件の質問
{count} 件の投票

1 件の回答

並べ替え方法: 最も役に立つ
  1. SurferOnWww 3,201 評価のポイント
    2024-11-05T01:01:35.66+00:00

    IIS 10.0でリクエストを受信してからASP.NETアプリケーション(ワーカースレッド)にデータを渡すまでの間、どこで時間がかかっているかを調べる方法はありますか

    「リクエストを受信してからASP.NETアプリケーション(ワーカースレッド)にデータを渡す」というのは、下の図(IIS がブラウザから要求を受けて応答を返すまでの流れ)で言うとどこに当たるのでしょう?

    enter image description here (出典: Microsoft 公式解説書 一目でわかる IIS 7.0)

    何にせよ、(1) IIS ログの time-taken と (2) アプリの処理時間を調べるということはすでにされていて、どこで時間がかかっているかは判明しているように見えますが?

    実測結果から問題は (2) より (1) がかなり大きいことで、質問はその原因は何かと言うことですか?

    であれば、自分が推測できるのは、(1) には network time が含まれる、すなわち最後のパケットに対するクライアントからの ACK を受け取るまでの時間が含まれるということで、ネットワークの問題がありそうということです。

    time-taken に network time が含まれることについて、詳しくは以下の記事を見てください。

    IIS ログの time-taken http://surferonwww.info/BlogEngine/post/2016/07/01/time-taken-of-iis-log.aspx

    他には、スレッドプールのスレッドが不足して要求がキューに溜まって待たされるということもあるかもしれません。その時間が time-taken に含まれるかどうかを明記してある Microsoft のドキュメントは見つかりませんが、time-taken は HTTP.sys が要求の最初のバイトを受け取った時点でカウントは始まるとのことですので、含まれていると思われます。

    ということで、「どこで時間がかかっているかを調べる」ということはすでに質問者さんが実施済みのように思われますが、いかがですか?


お客様の回答

回答は、質問作成者が [承諾された回答] としてマークできます。これは、ユーザーが回答が作成者の問題を解決したことを知るのに役立ちます。