快捷導航

阿里云上：“黑色30秒”走了，?“黑色1秒”來了，真相也許大白了

更新時間：2023年10月26日 13:15:02 投稿：mdxy-dxy

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

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

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

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

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

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

QPS

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

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

IIS請求處理流程圖

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

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

2. Arrival Rate不為0

Arrrival Rate

在QPS為0的時間點10:10:39，Arrival Rate的值在472-102之間（性能監(jiān)視器上點不出這個時間點的數(shù)值），說明有請求到達了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的數(shù)據(jù)分析，造成QPS為0的嫌疑對象只剩下3個：HTTP.SYS，WWW service，WAS。

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

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

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

所以，接下自然要去看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秒都有記錄。

IIS日志

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

這是啥情況？

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

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

那是不是因為網(wǎng)絡(luò)問題造成HTTP.SYS沒收到TCP確認包？這個可以通過HTTP ERROR日志進行確認，日志文件在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。

【進一步分析】

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

恍然大悟的是什么呢？

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

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

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

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

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

iis log