在昨天針對“黑色30秒”問題的分析中，我們猜測Requests Queued上升是由於正在處理的請求出不去（到達不了客戶端）。今天我們結合IIS日誌驗證這個猜測。

IIS日誌中有一個重要的指標——time-taken，time-taken不僅包含了請求在服務端執行的時間，還包含了響應的內容從服務端到達客戶端的時間（詳見以下的引用內容）。

Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.

計算time-taken的結束時間是在HTTP.sys將響應內容傳送給客戶端之後，等到客戶端發來確認包或者客戶端重置了TCP連線。

另外，“黑色30秒”只在訪問高峰期出現，我們覺得“黑色30秒”可能是某種小問題在高併發時的放大。

所以，今天我結合IIS日誌分析了一些小波動情況。下面是分析的情況：

1）13:47:13效能監視器中出現耗時562ms的請求

2）根據time-taken的計算方法，這個請求的time-taken肯定大於562ms，所以我們就在IIS日誌中找對應的記錄。

上圖就是這個請求在IIS日誌中的記錄，05:47:15是GMT時間，對應的北京時間是13:47:15。

time-taken竟然比Request Execution Time多了2秒多（2640ms），13:47:13 ASP.NET執行完請求傳送給客戶端之後，2秒之後才收到客戶端的確認包。

再看看13:47:15，效能監視器中究竟發生了什麼？

3）Requests Queued飆升

4）Arrival Rate突降

5）CPU消耗突降

6）Current Connections在上升，在後1秒（13:47:16）到達最高點。

13:47:13-13:47:15究竟發生了什麼？尤其是在13:47:15。。。

再來看另外一次波動情況：

竟然在IIS日誌中沒找到對應的記錄，這種情況很讓人懷疑是TCP連線被偷偷斷掉，也是就是昨天的

這篇博文先簡單分享一下今天的進展，接下來我們還要進行更多的分析與排查，阿里雲的同學也在努力排查問題，希望早日找到問題的原因並從根本上解決。