雲計算之路-阿里雲上：從ASP.NET線程角度對「黑色30秒」問題的全新分析

在這篇博文中，咱們拋開對阿里雲的懷疑，徹底從ASP.NET的角度進行分析，看能不能找到針對問題現象的更合理的解釋。

「黑色30秒」問題現象的主要特徵是：排隊的請求（Requests Queued）突增，到達HTTP.SYS的請求數（Arrival Rate）降低，QPS（Requests/Sec）降低，CPU消耗降低，Current Connections上升。

昨天晚上18:08左右發生了1次「黑色30秒」，正好藉此案例分析一下。

一、爲何Requests Queued會突增？

最直接的緣由是ASP.NET沒有可用的線程處理當前請求。爲何會沒有可用的線程呢？ASP.NET可用的線程畢竟是有限的，多是當時瞬間的併發請求太多，ASP.NET來不及建立足夠的線程處理這些請求。

咱們來看一下ASP.NET中線程相關的設置——machine.config中的processModel（位於C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Config）。

有4個相關設置：maxWorkerThreads（默認值是20）, maxIoThreads（默認值是20）, minWorkerThreads（默認值是1）, minIoThreads（默認值是1）。（這些設置是針對每一個CPU核）

咱們用的就是默認設置，因爲咱們的Web服務器是8核的，因而實際的maxWorkerThreads是160，實際的maxIoThreads是160，實際的minWorkerThreads是8，實際的minIoThreads是8。

基於這樣的設置，是否是若是瞬間併發請求是169，就會出現排隊？不是的，ASP.NET沒這麼傻！由於CLR 1秒只能建立2個線程（"The CLR ThreadPool injects new threads at a rate of about 2 per second. "），等線程用完時才建立，黃花菜都涼了。咱們猜想ASP.NET只是根據這個設置去預測線程池中的可用線程是否是緊張，是否是須要建立新的線程，以及建立多少線程。

那什麼狀況下會出現「黑色30秒」期間那樣的大量請求排隊？假如併發請求數平時是300，忽然某個瞬間併發請求數是600，超出了ASP.NET預估的所需的可用線程數，因而那些拿不到線程的請求只能排隊等待正在執行的請求釋放線程以及CLR建立新的線程。隨着時間的推移，釋放出來的線程+新建立的線程足以處理這些排隊的請求，就恢復了正常。

那如何驗證這個猜想呢？ 修改maxWorkerThreads, maxIoThreads, minWorkerThreads, minIoThreads的設置，讓ASP.NET提供更多的可用線程，目前咱們採用的設置以下：

<processModel enable="true"  requestQueueLimit="5000" maxWorkerThreads="100" maxIoThreads="100" minWorkerThreads="50" minIoThreads="50"/>

若是採用這個設置以後，「黑色30秒」現象幾乎不出現，就能驗證問題出在這個地方。如今主站www.cnblogs.com已經使用了這個設置，須要觀察一段時間進行驗證。

【啓示】

1) 經過Windows性能監視器監視\ASP.NET\Requests Queued能夠直觀地評估ASP.NET應用程序的吞吐能力（throughput）。

2) 經過ASP.NET異步編程（async/await）能夠有效減小可用線程緊張形成的請求排隊問題。

二、爲何Arrival Rate會降低？

（上圖中的橙色線條）

這是「黑色30秒」問題中最讓人不解的地方，ASP.NET中請求再怎麼排隊，怎麼會形成到達HTTP.SYS的請求數降低呢？一開始咱們老是不相信是請求排隊引發的Arrival Rate降低，可是監視圖中卻鐵證如山。

寫這篇博客以前，咱們忽然想通了！以前忽略了一個地方——當你打這篇博文時，第1個請求是html頁面，若是這個請求獲得正常響應，瀏覽器在加載這個頁面時會發出多個ajax請求；若是第1個請求被排隊，瀏覽器處於等待狀態，後續的ajax請求就不會發出，這樣到達HTTP.SYS的請求數就會降低。這也解釋了爲何有時會在「黑色30秒」的中間階段Arrival Rate會飆高，正是由於當時被排隊的請求所對應的頁面中有不少ajax，當它結束排隊被執行後，後續的不少ajax請求（可能排隊的不少是這樣的請求）到達了HTTP.SYS。

因而，咱們相信了是請求排隊引發的Arrival Rate降低。

【啓示】

不能把目光侷限於當前看到的問題表現，而要綜合考慮，將諸多因素聯繫起來理清各類現象之間的關係。

三、QPS降低

與Arrival Rate降低同理，QPS(Requests/Sec)與Arrival Rate是直接相關的，成正比關係。

因而，QPS降低也是由於請求排隊。

四、CPU消耗降低

也是同理，Arrival Rate與QPS降低，說明CPU要乾的活少了，天然消耗就降低。

因而，CPU消耗降低也是由於請求排隊。

五、Current Connections上升

Current Connections是請求排隊的一個直接表現，請求還沒被執行，鏈接固然會保持着。

因而，Current Connection上升也是由於請求排隊。

六、看一個新指標Requests Executing

（上圖綠色的線條表示的是Requests Executing）

在請求排隊的期間，正在被ASP.NET執行的請求數（Requests Executing）在增長，說明隨着被釋放出來的線程增多以及更多的新線程被建立，排列中的請求正在被愈來愈多地執行。這從側面說明了執行中的線程多是正常的，沒有被卡住。（接下來的IIS日誌信息會進一步驗證這一點）

因而，Requests Executing在增長也是由於請求被排隊，並且說明這個排隊是正常的，沒有哪一個地方卡住了。

七、再來看看IIS日誌中請求的time-taken

在「黑色30秒」階段，IIS日誌中沒有time-taken超過1s的請求！這說明了什麼？說明了正在被執行的請求處理速度很快，沒有什麼地方被卡住。。。除了由於可用線程不夠，請求被排隊。

因而，IIS日誌說明除了請求排隊，其餘地方一切正常。

【總結】

若是把「黑色30秒」問題歸因於ASP.NET線程問題，除了30秒左右的這個時間，其餘問題表現都獲得了更合理的解釋。

寫這篇博客以前，咱們當時以爲ASP.NET線程問題引發「黑色30秒」問題的可能性是80%，寫完這7點分析以後，咱們以爲可能性是99%，除非此次分析的「黑色30秒」與以前的「黑色30秒」不是同一個問題。

如今還須要咱們使用新設置(maxWorkerThreads="100", maxIoThreads="100", minWorkerThreads="50", minIoThreads="50")以後的驗證。

大結局即未來臨，重要的可能不是結局是什麼，而是其中的過程，咱們分享的也是解決問題的過程。

【「黑色30秒」相關博文】

雲計算之路-阿里雲上：Web服務器遭遇奇怪的「黑色30秒」問題

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

雲計算之路-阿里雲上：對「黑色30秒」問題的猜測

雲計算之路-阿里雲上：結合IIS日誌分析「黑色30秒」問題

雲計算之路-阿里雲上：藉助IIS Log Parser Studio分析「黑色30秒」問題

【參考資料】

ASP.NET Thread Usage on IIS 7.5, IIS 7.0, and IIS 6.0

Tuning IIS - machine.config settings