快捷導(dǎo)航

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

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

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

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

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

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

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

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

QPS

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

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

IIS請(qǐng)求處理流程圖

QPS為0是因?yàn)镮IS應(yīng)用程序池沒(méi)有收到底層轉(zhuǎn)發(fā)過(guò)來(lái)的請(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ì)列。

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

2. Arrival Rate不為0

Arrrival Rate

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

那這能不能說(shuō)明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ì)列。

通過(guò)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)，詳見(jiàn)云計(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日志中竟然無(wú)任何記錄

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

IIS日志

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

這是啥情況？

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

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

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

所以，造成IIS日志無(wú)記錄的嫌疑對(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)一步分析】

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

恍然大悟的是什么呢？

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

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

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

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

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

iis log