雲計算之路-阿里雲上：排查「黑色30秒」問題-爲何請求會排隊

針對Web服務器「黑色30秒」問題（詳見雲計算之路-阿里雲上：Web服務器遭遇奇怪的「黑色30秒」問題），通過分析，咱們準備從這個地方下手——爲何會出現\ASP.NET\Request Queued大於0的狀況（爲何請求會排隊）？

首先， 經過Windows性能監視器去觀察，看能不能找到這樣的線索——在什麼條件下會觸發請求排隊？

咱們在性能監視器中增長了1個監視指標——\HTTP Service Request Queues\Arrival Rate

Arrival Rate: Rate at which requests are arriving in the queue

這是一個針對IIS的底層HTTP.SYS的監視指標，從咱們的理解，認爲它最直接地反映了到達IIS的當前要處理的併發請求。

啓用這個Arrival Rate監視指標後，咱們觀察到了1次請求排隊的狀況（非「黑色30秒」故障場景）。

上圖中跳起的藍色就表現出現了請求排隊。

咱們來逐個指標看一下。

1. HTTP Service Request Queues\Arrival Rate（到達IIS底層的請求）

當時HTTP.SYS收到了465個併發請求。

2. Qequests/Sec(QPS，ASP.NET每秒處理的請求數)

當時ASP.NET的QPS是607。

3. Requests Queued（排隊的請求數）

【注意】出現請求排隊的時間點是11:03:54，而前2個指標高上去的時間點在11:03:55。

【重要線索】由此，咱們能夠得出這樣的線索：是先出現請求排隊（Requests Queued），而後纔出現Arrival Rate與QPS上升。是請求排隊引發Arrival Rate與QPS上升，而不是Arrival Rate與QPS上升引發請求排隊。

接下來經過其餘指標驗證這個想法。

4. Current Connections

IIS當前鏈接數高上去也在出現請求排隊以後。（成功驗證1）

5. CPU

CPU佔用也是在出現請求排隊以後才高上去的。（成功驗證2）

【分析結論】請求排隊纔是問題的緣由，而其餘表現只是請求排隊後的結果表現。

那在11:03:54，請求排隊時，其餘指標又是什麼狀況呢？

1. ArrivalRate只有218

2. QPS只有151

3. Current Connections在15如下（具體數值在性能監視器上顯示不出來）

4. CPU佔用只有10%

太奇怪了！在請求排隊時，其餘指標都處於低點——比正常狀況更低的點。

更奇怪的是到達IIS的請求比平時變少了，請求反而排隊了。

【猜測】

從這個監視到的表現看，咱們惟一能解釋得通的是：11:03:54，Web服務器彷佛在打瞌睡，處理能力全面降低；而後，11:03:55，Web服務器醒了過來，處理能力全面恢復，這時不只要處理當前的請求，還要處理以前排隊的請求，一會兒負載就高了上去。

難道誰給Web服務器下了藥？若是用的是物理機，咱們真的會懷疑是誰下的藥？但如今用的是虛擬機，在「被下藥」與「虛擬機問題」之間，哪一個更值得懷疑呢？。。。這個問題只能留給阿里雲的同窗，咱們再怎麼懷疑，也只能懷疑而已，沒法在虛擬機層面進行驗證。

【進一步的線索】

在寫這篇博客的期間，1臺服務器正好發生了「黑色30秒」，看看性能監視器中的相關表現：

1. Arrival Rate與Requests Queued

2. 加上Current Connections

3. 加上CPU

4. 加上Request Execution Time

並且此次接連來了2個「黑色30秒」。

【小結】

虛擬的世界很精彩，虛擬的世界也很無奈。從應用、從Windows的角度，咱們真的不知從何處理下手，咱們能作的只是找問題的線索。問題的解決可能真的須要阿里雲同窗們的努力！