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

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

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

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

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

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

問題現象一：出現問題時，在Windows性能監視器中的表現如下：

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

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

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

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

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

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

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

問題現象三：在問題期間，ASP.NET應用程序沒收到任何請求。

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

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

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

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

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

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

我們在Web服務器上通過Process Explorer拿到WAS進程的堆棧信息：

通過堆棧信息，我們發現WAS進程都會等SpinLock，當時我們一看到SpinLock眼前就一亮。因為之前阿里云技術人員問過我們有沒有在應用程序中使用SpinLock，美國服務器，說SpinLock在虛擬機上可能會引發CPU空轉（在物理機上沒這個問題），雖然我們沒有在應用程序中使用SpinLock，但是在WAS中用到了，而且是在Windows內核級別。

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

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

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

在網上找到了兩個重要的線索：

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秒鐘”期間的瞬時高并發請求會造成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。

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

這就是我們發這篇博客時的當前局面，已經完全不一樣了，從大海撈針變為做證明題。

阿里云會準備一臺安裝最新版Linux+最新版Xen的虛擬機以驗證問題是否依然存在。

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

spinlock.c源代碼詳見：

根據Kernel lockup running 3.0.0 and 3.2.0 on multiple EC2 instance types一文中的調用堆棧：

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

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

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