雲計算之路-阿里雲上：結合IIS日誌分析「黑色30秒」問題

在昨天針對「黑色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。

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