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

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

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

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

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

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

QPS為0是一種什么狀況呢？請(qǐng)看下圖：

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

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

2. Arrival Rate不為0

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

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

HTTP.SYS不能逃脫嫌疑，因?yàn)锳rrival Rate表示的是"Rate at which requests are arriving in the queue"，只是代表請(qǐng)求到了HTTP.SYS的隊(duì)列。如果HTTP.SYS的線程卡住了，請(qǐng)求還是能照常到達(dá)HTTP.SYS的隊(duì)列。

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

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

這次會(huì)不會(huì)也是卡在WAS呢？

上次將最大的嫌疑對(duì)象鎖定在WAS是因?yàn)樵诠收掀陂g，IIS日志中有靜態(tài)文件的響應(yīng)記錄（從HTTP.SYS緩存返回的），證明了HTTP.SYS當(dāng)時(shí)是正常的。

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

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

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

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

這是啥情況？

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

由于Arrival Rate有數(shù)據(jù)，說明不是因?yàn)闆]有請(qǐng)求到達(dá)造成IIS日志無記錄。

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

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

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

【進(jìn)一步分析】

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

恍然大悟的是什么呢？

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

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

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

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

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

從日志分析中看，很多請(qǐng)求time-taken都超過了1s，超過1s恰恰是因?yàn)镠TTP.SYS卡住了1秒。

阿里云SLB的日志也進(jìn)一步證明了這一點(diǎn)。

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

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

真相大白了？“黑色1秒”問題可以劃上圓滿的句號(hào)了？不，沒這么簡(jiǎn)單！

【大膽猜想】

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

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

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

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

黑色10秒，是因?yàn)閃AS被卡住，從Windows Server 2008升級(jí)至Windows Server 2012只是避開了問題的觸發(fā)條件。

黑色30秒，是因?yàn)锳SP.NET的線程被卡住。

黑色1秒，是因?yàn)镠TTP.SYS的線程被卡住。

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

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

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

【最新進(jìn)展更新】

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

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

最新評(píng)論