這次就有個詭異到不行的莫名現象搞得我差點走投無路準備燒香拜拜，花了一週的時間終於在靈光一閃的狀況下背我看破端倪。
故事是這樣的，我們系統有個結算金額的結帳作業被要求必須在極短的時間內 ( 2 秒 ) 完成，某日壓測結束後，赫然發現該結帳作業從 client 端的 log 判讀，耗時竟然高達需求的 10 倍以上( 30 秒 ) 有餘！甚至等到第一輪壓測結束後，該結帳作業在沒有新進交易的情況下，居然非常穩定地以相同緩慢的速度運行著。
調閱 Server App 自己的 log 比對，卻發現 App log 都顯示我們是在時限內完成作業，這中間的落差究竟是怎麼回事？網路慢？打開 ASP.NET 的 Performance Counter 和 Wireshark 側錄卻發現這段時間的落差完全卡在 IIS 和網卡之間，也就是網路傳輸是無辜的。於是我們整個懷疑的箭頭導向所採用的 3rd party framework 身上，因為我們的 App 是被 3rd party 的 framework container host 執行的。
聽從 System Team 的建議，使用了 YourKit profiler 這套可以監測所有 .NET 應用程式 ( 包含 ASP.NET ) 的工具，也顯示從 IIS ISAPI 進入點到出來的時間只有一秒多，簡直是無法理解。
怎麼想破頭都覺得這是我們自己 App layer 的問題，只針對特定一支作業有此現象，但卻又找不出這消失的 28 秒到底在做甚麼，也無法解釋為何其他環境的機器都無此問題。更恐怖的是，到了第二次壓測開始當天，這個現象霍然間消失，沒再出現！？然後壓測完後有逐步成長到消失了 9 秒半...，重開機數次都沒用。
就在我們決定換到另一台機器測試此現象是否和機器有關，吃驚地發現即使換到不同的機器此現象也一模一樣，連消失的秒數都絲毫不差。就在這震驚之中我頓悟了，這兩台機器的共同點就是 Database。而這個結帳作業會引發一個非同步呼叫又相當耗時的資料庫計算作業，由於這個計算作業的結果並不需要讓 client 端知道，所以我決定使用非同步的方式，在結帳作業完成後另外起一個新的執行緒 ( Thread ) 單獨進行這個工作，而讓前端的使用者盡快得到回應而不用等待 ( 註 )。
多執行緒我常寫，所以對這樣的設計是有把握可行的，然而這次我捨棄了自己控制底層執行緒的基本做法，改用包裝過看似方便好用的 System.ComponentModel.BackgroundWorker 來進行這次的設計。
經過測試，發現 BackgroundWorker 雖然是以獨立的執行緒處理工作，但它在 ASP.NET 中的行為模式並不容許『射後不理』的設計，反之，他在呼叫端的執行緒結束前會自動封鎖呼叫端執行緒，等待他自己的作業結束後才一起返回，這個特性卻是我在 MSDN 內翻遍文獻沒有被提到的一個大地雷。
為了確認與釐清這個 Class 的特性，我用上 .Net Reflector 神物細讀其實做的程式碼並寫同樣的 code 測試，終於發現關鍵點：
在呼叫 RunWorkerAsync 時，BackgroundWorker 事實上會呼叫 AsyncOperationManager.CreateOperation()，就是這個動作，會封鎖 ASP.NET HttpRequest 的執行緒回傳！
MSDN 沒有細說 BackgroundWorker 的使用特性與實作方式，真的讓我踩到好大一個地雷，差點就要接受某人的終極解決方案：Format 硬碟重灌整個作業系統...。XD...
註：這個非同步作業的特性就是會隨著累積的交易量增長而增長時間，所以其他環境沒有壓測所產生的大量交易來凸顯這個現象，而資料庫本身設計會每天做 Housekeeping purge 舊資料，於是乎系統恢復正常的原因來自於舊的壓測資料剛好被 purge 掉了。
沒有留言:
張貼留言