雲上真是無奇不有，這兩天我們什麼也沒動，“黑色30秒”招呼不打一聲就走了，而來了一位不速之客——“黑色1秒”；就寫了一篇博文，30秒就變成了1秒，看來多寫部落格是硬道理。
在上篇博文的評論中有人說——就30秒，有必要這麼較真嗎——當時想，別說30秒，哪怕1秒，我們也會較真。結果說1秒，1秒就來了。
我們看一下“黑色1秒”的情況（以下是今天上午Windows效能監視器的一次截圖）。
1. ASP.NET的QPS(Requests/Sec)為0
在10:10:39的時候，QPS為0（就出現了1秒）。這是“黑色1秒”期間最顯著的特徵，我們一開始也是通過這個特徵發現“黑色1秒”的。
QPS為0是一種什麼狀況呢？請看下圖：
QPS為0是因為IIS應用程式池沒有收到底層轉發過來的請求，從上圖中可以看出到達應用程式池之前的請求處理流程是這樣的：HTTP.SYS->WWW service->WAS。由此我們可以推斷，如果這3環節有一個地方卡住了，就會造成應用程式池收不到請求，從而QPS為0；當然，這有個前提條件——請求已經到達了HTTP.SYS的處理佇列。
接下來，我們就來找資料驗證請求是否到達了HTTP.SYS的處理佇列。
2. Arrival Rate不為0
在QPS為0的時間點10:10:39，Arrival Rate的值在472-102之間（效能監視器上點不出這個時間點的數值），說明有請求到達了HTTP.SYS。
那這能不能說明HTTP.SYS當時是正常呢？
HTTP.SYS不能逃脫嫌疑，因為Arrival Rate表示的是"Rate at which requests are arriving in the queue"，只是代表請求到了HTTP.SYS的佇列。如果HTTP.SYS的執行緒卡住了，請求還是能照常到達HTTP.SYS的佇列。
通過Arrival Rate的資料分析，造成QPS為0的嫌疑物件只剩下3個：HTTP.SYS，WWW service，WAS。
分析到這裡，自然就想起了去年遭遇的“黑色10秒”，當時的表現也是QPS為0，最後發現是卡在了WAS(Windows Process Activation Service)，詳見雲端計算之路-阿里雲上：超級奇怪的“黑色10秒鐘”。
這次會不會也是卡在WAS呢？
上次將最大的嫌疑物件鎖定在WAS是因為在故障期間，IIS日誌中有靜態檔案的響應記錄（從HTTP.SYS快取返回的），證明了HTTP.SYS當時是正常的。
所以，接下自然要去看IIS日誌。
3. QPS為0的前1秒IIS日誌中竟然無任何記錄
在QPS為0發生的時間點10:10:39的前1秒——10:10:38，IIS日誌中竟然無任何記錄（這也是無意中發現的，開始是通過10:10:39這個時間點去查詢，是有記錄的）。而這個時間點（10:10:38）的前1秒、後1秒都有記錄。
（上圖所用工具是Log Parser Studio）
這是啥情況？
有兩點很重要：1）記錄IIS日誌是HTTP.SYS乾的活；2）HTTP.SYS是在將響應內容發給客戶端後，收到客戶端的TCP確認包後記錄的。
由於Arrival Rate有資料，說明不是因為沒有請求到達造成IIS日誌無記錄。
那是不是因為網路問題造成HTTP.SYS沒收到TCP確認包？這個可以通過HTTP ERROR日誌進行確認，日誌檔案在C:\Windows\System32\LogFiles\HTTPERR資料夾中，對應的時間點並沒有TCP錯誤。
所以，造成IIS日誌無記錄的嫌疑物件應該在HTTP.SYS以及上層處理環節，結合第1部分對QPS為0的分析，還是這三者：HTTP.SYS，WWW service，WAS。
不管從上到下，還是從下到上，都是HTTP.SYS，WWW service，WAS。
【進一步分析】
本來準備寫這篇部落格時，還打算分析效能監視器中的其他指標。在寫的過程中，與曾經的“黑色10秒”進行對比時，突然恍然大悟！再次驗證了多寫部落格是硬道理！
恍然大悟的是什麼呢？
三個嫌疑物件分別是HTTP.SYS，WWW service，WAS，在“黑色10秒”中IIS日誌中有靜態檔案的記錄（來自HTTP.SYS的快取），說明HTTP.SYS是正常的；而在“黑色1秒”中，IIS日誌中沒有任何記錄，顯然說明了HTTP.SYS當時是不正常的。也就是說HTTP.SYS卡住了1秒種，更準確地說是HTTP.SYS的所有處理執行緒卡住了1秒。
當HTTP.SYS卡住時，請求轉發不到上層，應用程式池收不到請求，ASP.NET沒活幹，QPS自然為0。
當HTTP.SYS卡住時，ASP.NET處理完的請求發不出去，IIS日誌中自然沒記錄，而且記錄日誌就是HTTP.SYS乾的活。
於是，我們的分析結論是“黑色1秒”就是HTTP.SYS卡住了1秒。
而且卡住之後的1秒的IIS日誌也證明了這一點。
從日誌分析中看，很多請求time-taken都超過了1s，超過1s恰恰是因為HTTP.SYS卡住了1秒。
阿里雲SLB的日誌也進一步證明了這一點。
所以效能監視器上的表現只是HTTP.SYS卡住的結果：
為什麼效能監視器中QPS為0的發生點比IIS卡住要晚1秒呢，我們覺得可能是效能監視器取樣週期的原因。
真相大白了？“黑色1秒”問題可以劃上圓滿的句號了？不，沒這麼簡單！
【大膽猜想】
就在我們寫部落格的期間，又來了一個新的不速之客——“黑色5秒”。
黑色10秒，黑色30秒，黑色1秒，黑色5秒。。。就叫黑色n秒吧。
不管黑色多少秒，這些都只是問題的表象，而真正的黑色在虛擬機器層面，更準確地說就是Xen。
在某種觸發條件下，Windows中的執行緒在Xen的虛擬化處理中會被卡住。
黑色10秒，是因為WAS被卡住，從Windows Server 2008升級至Windows Server 2012只是避開了問題的觸發條件。
黑色30秒，是因為ASP.NET的執行緒被卡住。
黑色1秒，是因為HTTP.SYS的執行緒被卡住。
黑色5秒，不用管它了，如果問題不解決，還有更多的黑色n秒。。。
這就是我們的大膽猜想，這就是我們被“黑”無數次之後，最讓我們確信的一個猜想！
而我們能做的也只是猜想，下面就看阿里雲的了！
【最新進展更新】
2014年5月9日 10:43，阿里雲懷疑可能是Windows更新補丁引起的，準備將系統回滾至之前的某個時間點進行觀察。
2014年5月10日 10:15:58，再次出現“黑色1秒”（伺服器上安裝Windows補丁的最新時間是2014年3月5日）。