云上真是無奇不有，這兩天我們什么也沒動，“黑色30秒”招呼不打一聲就走了，而來了一位不速之客——“黑色1秒”；就寫了一篇博文，30秒就變成了1秒，看來多寫博客是硬道理。在上篇博文的評論中有人說——就30秒，有必要這么較真嗎——當(dāng)時想，別說30秒，哪怕1秒，我們也會較真。結(jié)果說1秒，1秒就來了。

云上真是無奇不有，這兩天我們什么也沒動，“黑色30秒”招呼不打一聲就走了，而來了一位不速之客——“黑色1秒”；就寫了一篇博文，30秒就變成了1秒，看來多寫博客是硬道理。

在上篇博文的評論中有人說——就30秒，有必要這么較真嗎——當(dāng)時想，別說30秒，哪怕1秒，我們也會較真。結(jié)果說1秒，1秒就來了。

我們看一下“黑色1秒”的情況（以下是今天上午Windows性能監(jiān)視器的一次截圖）。

1. ASP.NET的QPS(Requests/Sec)為0

在10:10:39的時候，QPS為0（就出現(xiàn)了1秒）。這是“黑色1秒”期間最顯著的特征，我們一開始也是通過這個特征發(fā)現(xiàn)“黑色1秒”的。

QPS為0是一種什么狀況呢？請看下圖：

QPS為0是因為IIS應(yīng)用程序池沒有收到底層轉(zhuǎn)發(fā)過來的請求，從上圖中可以看出到達(dá)應(yīng)用程序池之前的請求處理流程是這樣的：HTTP.SYS->WWW service->WAS。由此我們可以推斷，如果這3環(huán)節(jié)有一個地方卡住了，就會造成應(yīng)用程序池收不到請求，從而QPS為0；當(dāng)然，這有個前提條件——請求已經(jīng)到達(dá)了HTTP.SYS的處理隊列。

接下來，我們就來找數(shù)據(jù)驗證請求是否到達(dá)了HTTP.SYS的處理隊列。

2. Arrival Rate不為0

在QPS為0的時間點10:10:39，Arrival Rate的值在472-102之間（性能監(jiān)視器上點不出這個時間點的數(shù)值），說明有請求到達(dá)了HTTP.SYS。

那這能不能說明HTTP.SYS當(dāng)時是正常呢？

HTTP.SYS不能逃脫嫌疑，因為Arrival Rate表示的是"Rate at which requests are arriving in the queue"，只是代表請求到了HTTP.SYS的隊列。如果HTTP.SYS的線程卡住了，請求還是能照常到達(dá)HTTP.SYS的隊列。

通過Arrival Rate的數(shù)據(jù)分析，造成QPS為0的嫌疑對象只剩下3個：HTTP.SYS，WWW service，WAS。

分析到這里，自然就想起了去年遭遇的“黑色10秒”，當(dāng)時的表現(xiàn)也是QPS為0，最后發(fā)現(xiàn)是卡在了WAS(Windows Process Activation Service)，詳見云計算之路-阿里云上：超級奇怪的“黑色10秒鐘”。

這次會不會也是卡在WAS呢？

上次將最大的嫌疑對象鎖定在WAS是因為在故障期間，IIS日志中有靜態(tài)文件的響應(yīng)記錄（從HTTP.SYS緩存返回的），證明了HTTP.SYS當(dāng)時是正常的。

所以，接下自然要去看IIS日志。

3. QPS為0的前1秒IIS日志中竟然無任何記錄

在QPS為0發(fā)生的時間點10:10:39的前1秒——10:10:38，IIS日志中竟然無任何記錄（這也是無意中發(fā)現(xiàn)的，開始是通過10:10:39這個時間點去查詢，是有記錄的）。而這個時間點（10:10:38）的前1秒、后1秒都有記錄。

（上圖所用工具是Log Parser Studio）

這是啥情況？

有兩點很重要：1）記錄IIS日志是HTTP.SYS干的活；2）HTTP.SYS是在將響應(yīng)內(nèi)容發(fā)給客戶端后，收到客戶端的TCP確認(rèn)包后記錄的。

由于Arrival Rate有數(shù)據(jù)，說明不是因為沒有請求到達(dá)造成IIS日志無記錄。

那是不是因為網(wǎng)絡(luò)問題造成HTTP.SYS沒收到TCP確認(rèn)包？這個可以通過HTTP ERROR日志進行確認(rèn)，日志文件在C:\Windows\System32\LogFiles\HTTPERR文件夾中，對應(yīng)的時間點并沒有TCP錯誤。

所以，造成IIS日志無記錄的嫌疑對象應(yīng)該在HTTP.SYS以及上層處理環(huán)節(jié)，結(jié)合第1部分對QPS為0的分析，還是這三者：HTTP.SYS，WWW service，WAS。

不管從上到下，還是從下到上，都是HTTP.SYS，WWW service，WAS。

【進一步分析】

本來準(zhǔn)備寫這篇博客時，還打算分析性能監(jiān)視器中的其他指標(biāo)。在寫的過程中，與曾經(jīng)的“黑色10秒”進行對比時，突然恍然大悟！再次驗證了多寫博客是硬道理！

恍然大悟的是什么呢？

三個嫌疑對象分別是HTTP.SYS，WWW service，WAS，在“黑色10秒”中IIS日志中有靜態(tài)文件的記錄（來自HTTP.SYS的緩存），說明HTTP.SYS是正常的；而在“黑色1秒”中，IIS日志中沒有任何記錄，顯然說明了HTTP.SYS當(dāng)時是不正常的。也就是說HTTP.SYS卡住了1秒種，更準(zhǔn)確地說是HTTP.SYS的所有處理線程卡住了1秒。

當(dāng)HTTP.SYS卡住時，請求轉(zhuǎn)發(fā)不到上層，應(yīng)用程序池收不到請求，ASP.NET沒活干，QPS自然為0。

當(dāng)HTTP.SYS卡住時，ASP.NET處理完的請求發(fā)不出去，IIS日志中自然沒記錄，而且記錄日志就是HTTP.SYS干的活。

于是，我們的分析結(jié)論是“黑色1秒”就是HTTP.SYS卡住了1秒。

而且卡住之后的1秒的IIS日志也證明了這一點。

從日志分析中看，很多請求time-taken都超過了1s，超過1s恰恰是因為HTTP.SYS卡住了1秒。

阿里云SLB的日志也進一步證明了這一點。

所以性能監(jiān)視器上的表現(xiàn)只是HTTP.SYS卡住的結(jié)果：

為什么性能監(jiān)視器中QPS為0的發(fā)生點比IIS卡住要晚1秒呢，我們覺得可能是性能監(jiān)視器采樣周期的原因。

真相大白了？“黑色1秒”問題可以劃上圓滿的句號了？不，沒這么簡單！

【大膽猜想】

就在我們寫博客的期間，又來了一個新的不速之客——“黑色5秒”。

黑色10秒，黑色30秒，黑色1秒，黑色5秒。。。就叫黑色n秒吧。

不管黑色多少秒，這些都只是問題的表象，而真正的黑色在虛擬機層面，更準(zhǔn)確地說就是Xen。

在某種觸發(fā)條件下，Windows中的線程在Xen的虛擬化處理中會被卡住。

黑色10秒，是因為WAS被卡住，從Windows Server 2008升級至Windows Server 2012只是避開了問題的觸發(fā)條件。

黑色30秒，是因為ASP.NET的線程被卡住。

黑色1秒，是因為HTTP.SYS的線程被卡住。

黑色5秒，不用管它了，如果問題不解決，還有更多的黑色n秒。。。

這就是我們的大膽猜想，這就是我們被“黑”無數(shù)次之后，最讓我們確信的一個猜想！

而我們能做的也只是猜想，下面就看阿里云的了！

【最新進展更新】

2014年5月9日 10:43，阿里云懷疑可能是Windows更新補丁引起的，準(zhǔn)備將系統(tǒng)回滾至之前的某個時間點進行觀察。

2014年5月10日 10:15:58，再次出現(xiàn)“黑色1秒”（服務(wù)器上安裝Windows補丁的最新時間是2014年3月5日）。

最新評論