在昨天針對“黑色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連接被偷偷斷掉，也是就是昨天的猜想2。
這篇博文先簡單分享一下今天的進展，接下來我們還要進行更多的分析與排查，阿里雲的同學也在努力排查問題，希望早日找到問題的原因並從根本上解決。