【必殺】為應用程式池“XXX”提供服務的程式在與 Windows Process Activation Service 通訊時出現嚴重錯誤。該程式 ID 為“XXXX”。資料欄位包含錯誤號。

jackchain發表於2022-01-20

之前寫過一篇文章,https://www.cnblogs.com/qidian10/p/6028784.html 解釋如何解決此類問題,但現在回過頭來想一下,之前的文章還是太過淺顯,無法完全有效的徹底解決此類問題。

近期因為工作原因,這個問題又凸顯出來,這裡做下解決思路,通過如下的解決思路基本可以應對任何此類這樣的問題,能夠快速準確的定位原因。

 

一、事發背景

謀SaaS架構產品,基於.net framework 跑在iis上,負載均衡3臺web;

情況是每天的非固定時間會報一次cpu 100%的警告,部分情況下可在1分鐘左右的時間自動恢復;訪問量大的情況下持續很久需要人工干預;直觀的表現如下:

1)cpu瞬間打滿

2)iis請求佇列排隊嚴重

3)附加著帶來若干redis請求異常,部分第三方api請求異常等

4)總之客戶怨聲載道,給系統打上“卡”的標籤,投訴不斷

 

 

 

 

 

 

二、分析問題

由於系統不是經常性的卡頓,是偶發性的,基本定性為幾個方向:

1、某一個不是特別常用的請求觸發,或者某一個不是經常能夠被操作的功能點,觸發導致的;

2、redis請求堵塞導致:這個最先排除,因為卡頓的時候,其他負載組的並不卡;

3、最後一張圖的直觀反饋是session阻塞

由於歷史原因,系統保留了部分session的程式碼,根據資料顯示,大併發情況下請求同一個session,利用session預設管理器的時候會導致請求排隊。

https://stackoverflow.com/questions/16570855/requests-hanging-on-session-module-on-iis-7-5/27481000#27481000

https://blog.csdn.net/anyi2404/article/details/102251579

花了一個晚上時間,把系統裡所有帶session的引用全部重構掉,上線生產後,但是問題依舊


那麼只有第一個可能了,按照這個思路排查這個期間發生的所有請求,按照每個請求的引數等情況去模擬,是可以復現問題的,但是這個工作量大的驚人,卡頓期間的url請求是幾乎千條記錄,靠人工是不現實的,另一主要原因是即使通過該方法解決了本問題,也不可以複製解決方案去應對未來的問題。所以這個方案放棄掉了。

 

三、開始抓dump分析

按照以往的慣例,每次卡頓的時候只需要在工作管理員程式-右鍵轉儲存,即可獲取到dump檔案,然後分析問題即可;但是該方式有個“坑”就是你抓取dump的時候不能存在應用程式池重啟的情況,必須保證都是同一個應用程式池程式,否則的話你可能無法分析到真正的原因。

所以通過人工的方式抓取存在一定的運氣性,常規類的一般都可以解決。但這次我們事後分析恰好踩了這次的坑,每次分析dump,幾乎都是常規類的請求,程式碼覆盤上基本不會有效能問題。

 

四、如何抓取到正確的dump包(工具一)

利用procdump:https://docs.microsoft.com/en-us/sysinternals/downloads/procdump 基本命令如下

procdump -ma -s 5 -n 2 -c 70  2160

定義:當-c 70 cpu超過70%的時候,連續超過-s 5秒的時候,抓取-n 2個dump,該操作繫結程式2160

利用工具抓取可以有效避免dump不準確的問題,執行上述命令後,伺服器會自動開啟監控任務,一單觸發,自動打包dump檔案

 

 

 

 

 

 

五、分析dump

之前寫過一份簡易版本的分析方案:http://www.cnunify.com/help/helpDetail?id=6abdffd4-c4c6-4310-ac02-32d62e7e62a7&title=%E7%9F%A5%E8%AF%86%E5%BA%93

更全面的可以參考園子大佬的:https://www.cnblogs.com/huangxincheng/category/1967355.html

 

毫無疑問大量的請求在等待被執行,正在佇列中的還有283,足以讓cpu高起來,那麼接下來就看,到底是什麼原因導致請求堵塞了。

經過不斷的抓包分析,最終根據請求cpu佔用時間排序靠前的執行緒,定位到一個方法BulkInsert(當然804個請求佇列裡面還有很多個其他型別的方法請求,需要專業,也需要運氣)

 

 

 

之前沒有特別注意這個方法,認為就是一個普通的批量插入,而且本地執行的時候也會很快,經過各種反覆猜想後,最後突然想起一個問題:

因為EF自身的問題,批量插入、更新等效率太低,所以替換了一個第三方元件來支援:Z.EntityFramework.Extensions,這個元件有一個毛病,就是預熱的時候會非常慢,必須等待預熱完成才可以正常執行,預熱期間的請求都會排隊等待。

講人話就是:第一次呼叫BulkInsert方法,會觸發預熱,會非常慢(看你實體模型數量),之後就正常毫秒級別了。

那麼是什麼原因會導致Z.EntityFramework.Extensions預熱呢?

只有一個可能就是這個期間發生了應用程式池的重啟,某些原因導致了異常,觸發了重啟。

恍然大悟,之前分析的時候就注意到was程式會崩潰,並報錯“為應用程式池“XXX”提供服務的程式在與 Windows Process Activation Service 通訊時出現嚴重錯誤。該程式 ID 為“XXXX”。資料欄位包含錯誤號”

 

 

 

 

六、確認邏輯

到目前為止,基本定性了問題原因:某些請求,導致was(w3pw.exe)崩潰,進而應用程式池重啟,重啟觸發了Z.EntityFramework.Extensions預熱,預熱過程帶來了所有請求排隊,訪問量越高,阻塞越長,嚴重情況下伺服器可能整體當機!

 

七、究其根本,解決問題

兩個方式:要麼替換Z.EntityFramework.Extensions元件,但治標不治本;要麼找到真正觸發w3pw.exe崩潰和應用程式池重啟的程式碼;很顯然必須究其根本。

 

八、如何抓取到正確的dump包(工具二)

本塊是文章重點,如何在異常情況下抓到最正確的dump包是分析問題的關鍵,上面介紹了一種抓dump方式,但是應對應用程式池崩潰問題,procdump工具並不奏效!

此處必須祭出大殺器:DebugDiaog2.0,實際只需要這一個工具即可。https://www.microsoft.com/en-us/download/details.aspx?id=49924

微軟官方的參考demo:https://docs.microsoft.com/en-us/iis/troubleshoot/performance-issues/troubleshooting-high-cpu-in-an-iis-7x-application-pool

中文翻譯版:https://cloud.tencent.com/developer/article/1619150?from=15425

基本按照文章的內容照做即可抓到正確的dump包。

DebugDiaog提供了當cpu、記憶體等資源異常時候自動監控和抓dump,也提供了當應用程式crash的時候自動抓dump。

 

按照對應操作步驟去建立規則rule即可

效能的抓包參考:https://docs.microsoft.com/en-us/iis/troubleshoot/performance-issues/troubleshooting-high-cpu-in-an-iis-7x-application-pool

crash抓包參考:https://stackoverflow.com/questions/18335678/how-to-debug-w3wp-clr-dll-error?noredirect=1

crash抓包的時候注意裡面有個步驟需要選擇型別,比如是棧溢位,還是其他異常,這個資訊來自

 

 

九、顯出原形

利用第八步驟,抓到合適dump之後,即可正常分析問題了,也沒必要用windbg分析了,直接用debugdiag自帶的分析器,掛上去分析

 

結果:

 

至此罪魁禍首已經定位,找相關人員處理掉即可。

 

十、能學到點什麼,總結精髓

1、dump是什麼

2、如何抓取普通的dump,工具procdump

3、如何抓取特殊異常情況下最正確的dump,工具debugdiag,這是最重要的一步

4、如何分析dump內容,!t、!tp、.cordll -lp <path>、!runaway、!~[thread]s、!clrstack等等

5、Z.EntityFramework.Extensions的坑不得不重視

 

參考文獻:

https://stackoverflow.com/questions/18335678/how-to-debug-w3wp-clr-dll-error?noredirect=1

 

相關文章