云計(jì)算之路-阿里云上：超級奇怪的“黑色10秒鐘”

自從5月24日發(fā)布博文（云計(jì)算之路-阿里云上：兩個重要突破）之后，情況有了明顯改善。但是我們不但沒有絲毫的放松，反而變得更加艱苦。我們被一個非常非常奇怪的問題所困擾，這段時間我們與阿里云一起在努力與之作艱苦斗爭。 這個問題每天會出現(xiàn)十幾次，每次

自從5月24日發(fā)布博文（云計(jì)算之路-阿里云上：兩個重要突破）之后，情況有了明顯改善。但是我們不但沒有絲毫的放松，反而變得更加艱苦。我們被一個非常非常奇怪的問題所困擾，這段時間我們與阿里云一起在努力與之作艱苦斗爭。

這個問題每天會出現(xiàn)十幾次，每次出現(xiàn)都會持續(xù)10秒鐘（“黑色10秒鐘”由此而來）。

為了更清楚地表達(dá)問題，大家先看一張IIS處理請求的流程圖（注：問題不是來自IIS，而是通過IIS定位出問題）。

（注：這張圖對理解我們遇到的問題很重要）

問題現(xiàn)象一：出現(xiàn)問題時，在Windows性能監(jiān)視器中的表現(xiàn)如下：

上圖中綠色線條表示的是Web Service->Current Connections（Web Service就是第一張圖中的World Wide Web Pulishing Service），出現(xiàn)問題時Current Connections會突然跳上去（通常會跳到200以上）。我們猜測這是瞬間的高并發(fā)請求引起的。（這種瞬間高并發(fā)請求在壓力測試中很難模擬，所以我們一直未能通過壓力測試重現(xiàn)這個問題）

上圖中棕色線條表示的是ASP.NET Applications->Requests/s，在出問題時這個值會變?yōu)?，服務(wù)器空間，也就是ASP.NET沒處理任何請求。而且ASP.NET->Requests Queued與Requests Current也都為0，說明ASP.NET不僅沒有處理請求，可能根本沒收到請求。

上圖中藍(lán)色線條表示的是TCPv4->Connections Established，虛擬主機(jī)，出現(xiàn)問題時這個值也會飚上去，通常在1000以上，它稍稍滯后于Current Connections的上升。

上圖中紅色線條表示的是% Processor Time，出現(xiàn)問題時，Requests/s為0，但CPU卻沒有明顯下降（本來絕大部分CPU占用都消耗在處理請求上）。這就是問題最奇特的地方，CPU被占用了，卻什么活也沒干。

問題現(xiàn)象二：在問題期間，IIS的http.sys能正常接收請求，但不響應(yīng)請求，等到“黑色10秒鐘”之后才響應(yīng)累積的請求。

1. 在禁用Output Caching的情況下，“黑色10秒鐘”期間的IIS日志顯示IIS沒有對任何請求進(jìn)行響應(yīng)。等到“黑色10秒鐘”一過，會出現(xiàn)time-taken為10s, 9s, 8s...這樣的請求，這些請求恰恰是在“黑色10秒鐘”期間收到的，只是在“黑色10秒鐘”之后才進(jìn)行響應(yīng)。

2. 如果開啟Output Caching，會在IIS日志中看到“黑色10秒鐘”期間IIS會正常響應(yīng)一些靜態(tài)文件。實(shí)際上這些靜態(tài)文件是http.sys通過Kernel-Mode caching返回的。這說明在問題期間，http.sys是正常的。

問題現(xiàn)象三：在問題期間，ASP.NET應(yīng)用程序沒收到任何請求。

我們在應(yīng)用程序中記錄了訪問日志，發(fā)現(xiàn)在“黑色10秒鐘”期間應(yīng)用程序也沒有收到請求，確認(rèn)了ASP.NET根本沒收到請求，也就是說請求可能沒有進(jìn)入到w3wp進(jìn)程（應(yīng)用程序池我們用的是集成模式）。

綜合上面的三個現(xiàn)象，我們可以分析出，在“黑色10秒鐘”期間http.sys正常，請求沒有到達(dá)w3wp進(jìn)程。問題肯定出在http.sys->w3wp之間的某個環(huán)節(jié)。

再來看一下IIS請求處理流程圖：

從圖中可以知道，在http.sys->w3wp之間還有WWW service與WAS。而在性能監(jiān)視器中顯示“黑色10秒鐘”期間WWW service的Current Connections的值是跳高的，說明WWW service也收到了請求。所以剩下的最大的嫌疑對像就是WAS。而WAS的主要任務(wù)就是將請求轉(zhuǎn)發(fā)給對應(yīng)的w3wp，如果它出問題了，w3wp自然收不到請求。

WAS resides in User Layer of IIS. It takes the request from HTTP.SYS and pass it to the respective application pool.

在之前我們走了很多很多彎路，但當(dāng)我們把焦點(diǎn)放在WAS上，就開辟了一條最有希望的問題解決之路。

我們在Web服務(wù)器上通過Process Explorer拿到WAS進(jìn)程的堆棧信息：

通過堆棧信息，我們發(fā)現(xiàn)WAS進(jìn)程都會等SpinLock，當(dāng)時我們一看到SpinLock眼前就一亮。因?yàn)橹鞍⒗镌萍夹g(shù)人員問過我們有沒有在應(yīng)用程序中使用SpinLock，美國服務(wù)器，說SpinLock在虛擬機(jī)上可能會引發(fā)CPU空轉(zhuǎn)（在物理機(jī)上沒這個問題），雖然我們沒有在應(yīng)用程序中使用SpinLock，但是在WAS中用到了，而且是在Windows內(nèi)核級別。

我們之前提到過在“黑色10秒鐘”期間CPU占用沒有明顯下降（CPU被占用卻不干活）的奇特現(xiàn)象如果用CPU空轉(zhuǎn)來解決，簡直是完美無缺。

在眼前一亮之后，我們意識到這是非常耀眼的一亮，一定要深挖下去。

SpinLock是在Windows內(nèi)核級別使用了，而Windows內(nèi)核出問題的可能性比虛擬機(jī)(阿里云用的是Xen)出問題的可能性要小很多很多。所以我們把嫌疑對象放在了Xen上。

在網(wǎng)上找到了兩個重要的線索：

1. Kernel lockup running 3.0.0 and 3.2.0 on multiple EC2 instance types

Running lots of threads which utilize spinlocks, we hit a stage where the spinlock is still locked but none of the CPUs seem to be actively holding it.

注：“黑色10秒鐘”期間的瞬時高并發(fā)請求會造成lots of threads。

2. xen: Send spinlock IPI to all waiters

There is a loophole between Xen's current implementation of pv-spinlocks and the scheduler.

注：Xen在處理spinlock時的確存在bug。

從這兩個線索中，我們可以作出這樣的假設(shè)——“黑色10秒鐘”很可能是Xen的bug引起的，接下來要做的就是證明這個假設(shè)。

這就是我們發(fā)這篇博客時的當(dāng)前局面，已經(jīng)完全不一樣了，從大海撈針變?yōu)樽鲎C明題。

阿里云會準(zhǔn)備一臺安裝最新版Linux+最新版Xen的虛擬機(jī)以驗(yàn)證問題是否依然存在。

我們準(zhǔn)備從Xen的spinlock.c源代碼中找出為什么每次都是10秒的證據(jù)。

spinlock.c源代碼詳見：

根據(jù)Kernel lockup running 3.0.0 and 3.2.0 on multiple EC2 instance types一文中的調(diào)用堆棧：

目前我們初步判斷“10秒鐘”可能發(fā)生在調(diào)用xen_proll_irq_timeout時，源代碼見。

在Xen的源代碼中找出“10秒鐘”的來源不知要花多少時間，所以先寫了這篇博文把當(dāng)前的情況向大家匯報(bào)一下——我們與阿里云一直在努力解決問題。

聲明：本網(wǎng)頁內(nèi)容旨在傳播知識，若有侵權(quán)等問題請及時與本網(wǎng)聯(lián)系，我們將在第一時間刪除處理。TEL:177 7030 7066 E-MAIL:11247931@qq.com