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

Question

.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のログがでてきます。）

Answer 1

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

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

(出典: 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 が要求の最初のバイトを受け取った時点でカウントは始まるとのことですので、含まれていると思われます。

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