雲計算之路-阿里雲上：黑色1秒，微軟的問題還是阿里雲的問題？

“黑色1秒”問題經過一個多月的艱苦奮戰，今天終於取得了重要進展！我們終於有了足夠的數據證明不是微軟IIS的問題，就是阿里雲Xen虛擬機的問題。

這篇博文分享的是我們如何進行證明的，而且這次證明連Window性能監視器都不需要。

下面我們來分析一下今天10:37:35出現的“黑色1秒”（下面所用的IIS日志分析工具是Log Parser Studio，這是我們在排查“黑色1秒”問題期間對我們幫助最大的一個工具）。

1. 先從IIS日志中找出哪些時間點發生了“黑色1秒”。

a) 在Log Parser Studio中所用的日志查詢語句（查詢的是10:00-10:59的IIS日志文件）

SELECT  TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as Time, COUNT(time) as Requests
FROM '[LOGFILEPATH]'
GROUP BY TIME
HAVING COUNT(time) < 20

b) 日志查詢結果

發生了2次，我們只分析10:37:35這次。

注：IIS是在請求處理完成后將響應內容發給客戶端，客戶端發來TCP ACK包時才寫入日志。

2. “黑色1秒”期間，IIS日志中的記錄情況

a) 日志查詢語句

SELECT  TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as time,cs-method,cs-uri-stem,time-taken
FROM '[LOGFILEPATH]'
WHERE TO_LOCALTIME(time)='10:37:35'

b) 日志查詢結果

為什么這12個請求能正常處理？因為這些請求走的是http.sys的kernel-mode緩存（見下圖），這證明了在“黑色1秒”期間http.sys工作正常，也從側面證明了網絡層面沒問題。

3. “黑色1秒”前后IIS日志中的記錄情況

a) IIS日志查詢語句

SELECT TO_STRING(TO_LOCALTIME(time), 'hh:mm:ss') as Time, count(time) as Requests
FROM '[LOGFILEPATH]'
WHERE TO_LOCALTIME(time) > '10:37:33' AND TO_LOCALTIME(time) < '10:37:38'
GROUP BY time

b) 日志查詢結果

通過對比“黑色1秒”前后處理的請求量，可以分析出，10:37:35收到的請求， 除了http.sys緩存中有的內容，其他請求都被延遲到10:37:36才被處理。

c) 查詢10:37:36日志中time-taken超過1秒的請求

可以推斷這些請求是在10:37:35收到的，然后在10:37:36才被處理。

通過1,2,3的分析，我們可以得出結論1：“黑色1秒”是因為請求在http.sys之后的處理環節中被卡住了1秒。

4. 看一下ASP.NET應用程序中的日志情況

在ASP.NET應用程序中我們記錄了執行時間超過1秒的請求，代碼如下：

public class Global : System.Web.HttpApplication
{
    protected void Application_BeginRequest(Object sender, EventArgs e)
    {
        Context.Items.Add("start-time", DateTime.Now);
    }

    protected void Application_EndRequest(Object sender, EventArgs e)
    {
        if (Context.Items["start-time"] != null)
        {
            var startTime = Convert.ToDateTime(Context.Items["start-time"]);
            if (startTime != default(DateTime))
            {
                var duration = (int)(DateTime.Now - startTime).TotalMilliseconds;
                if (duration > 1000)
                {                     
                    Logger.Default.Info("EndRequest-request-execution-time", duration + "ms", Context);
                }
            }
        }
    }
}

如果“黑色1秒”期間，請求已經進入ASP.NET，在應用程序執行過程中卡住了，那么在應用的日志中會記錄這些執行時間超過1秒的請求。

查看應用日志的結果是：不僅10:37:36沒有記錄到有超過1秒的請求，就連10:37:36-10:37:58也沒有超過1秒的請求。

由此我們可以得到結論2：“黑色1秒”期間，請求根本沒有進入ASP.NET。

5. 分析小結

通過結論1與結論2，我們再次以真實的數據證明了“黑色1秒”的確是發生在http.sys與ASP.NET的中間處理環節。

那誰負責這些中間處理環節呢？——IIS的核心模塊（user-mode的非托管代碼），比如w3tp->w3dt->iiscore->webengine->wbhst_pm（詳見之前的博文“黑色1秒”最新線索——w3tp與w3dt）。

所以，我們對“黑色1秒”問題分析的最終結論是——“黑色1秒”發生IIS的user-mode核心模塊。

如果用的是物理機，我們會毫無猶豫地將矛頭指向微軟；但是我們用的是虛擬機，矛頭又多了一個指向——阿里雲。

考慮到微軟IIS的用戶要遠遠遠遠多於阿里雲的用戶，僅僅從情理上，矛頭也會指向阿里雲更多一些。

我們用了10年多的IIS，之前從來沒有遇到過IIS的底層問題；而我們僅用了1年多的阿里雲，遇到的問題不計其數，僅僅從出問題的概率上，矛頭也指向阿里雲更多一些。

如果您關注過去年我們在阿里雲上遇到“黑色10秒”問題，你會發現，如果把“1秒”改成“10秒”，這兩個“黑色”竟然驚人的相似。而當時“黑色10秒”問題只是從表面解決，從Windows Server 2008 R2升級至Windows Server 2012，阿里雲並沒有從虛擬化底層去解決。僅僅從曾經的經歷，矛頭也指向阿里雲更多一些。

6. 問題的最終驗證

我們想到的最簡單但也許是最難的驗證方法，其他環境都不變，把虛擬機換成物理機。這只有阿里雲可以做到。

7. 建議嘗試的臨時解決方案

從Windows Server 2012升級至Windows Server 2012 R2，也就是將IIS從8.0升級至8.5，也許可以避開這個問題。這也只有阿里雲可以做到。