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

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

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

為了更清楚地表達(dá)問(wèn)題，大家先看一張IIS處理請(qǐng)求的流程圖（注：?jiǎn)栴}不是來(lái)自IIS，而是通過(guò)IIS定位出問(wèn)題）。

（注：這張圖對(duì)理解我們遇到的問(wèn)題很重要）

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

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

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

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

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

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

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

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

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

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

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

再來(lái)看一下IIS請(qǐng)求處理流程圖：

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

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上，就開(kāi)辟了一條最有希望的問(wèn)題解決之路。

我們?cè)赪eb服務(wù)器上通過(guò)Process Explorer拿到WAS進(jìn)程的堆棧信息：

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

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

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

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

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

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秒鐘”期間的瞬時(shí)高并發(fā)請(qǐng)求會(huì)造成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時(shí)的確存在bug。

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

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

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

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

spinlock.c源代碼詳見(jiàn)：

根據(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時(shí)，源代碼見(jiàn)。

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

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