執行緒池運用不當的一次線上事故
阿新 • • 發佈：2020-06-12
在高併發、非同步化等場景，執行緒池的運用可以說無處不在。執行緒池從本質上來講，即通過空間換取時間，因為執行緒的建立和銷燬都是要消耗資源和時間的，對於大量使用執行緒的場景，使用池化管理可以延遲執行緒的銷燬，大大提高單個執行緒的複用能力，進一步提升整體效能。
今天遇到了一個比較典型的線上問題，剛好和執行緒池有關，另外涉及到死鎖、jstack命令的使用、JDK不同執行緒池的適合場景等知識點，同時整個調查思路可以借鑑，特此記錄和分享一下。
### **01 業務背景描述** 該線上問題發生在廣告系統的核心扣費服務，首先簡單交代下大致的業務流程，方便理解問題。  綠框部分即扣費服務在廣告召回扣費流程中所處的位置，簡單理解：當用戶點選一個廣告後，會從C端發起一次實時扣費請求(CPC，按點選扣費模式)，扣費服務則承接了該動作的核心業務邏輯：包括執行反作弊策略、建立扣費記錄、click日誌埋點等。
### **02 問題現象和業務影響** 12月2號晚上11點左右，我們收到了一個線上告警通知：扣費服務的執行緒池任務佇列大小遠遠超出了設定閾值，而且佇列大小隨著時間推移還在持續變大。詳細告警內容如下： 
相應的，我們的廣告指標：點選數、收入等也出現了非常明顯的下滑，幾乎同時發出了業務告警通知。其中，點選數指標對應的曲線表現如下：  該線上故障發生在流量高峰期，持續了將近30分鐘後才恢復正常。
### **03 問題調查和事故解決過程** 下面詳細說下整個事故的調查和分析過程。 **第1步**：收到執行緒池任務佇列的告警後，我們第一時間查看了扣費服務各個維度的實時資料：包括服務呼叫量、超時量、錯誤日誌、JVM監控，均未發現異常。 **第2步**：然後進一步排查了扣費服務依賴的儲存資源（mysql、redis、mq），外部服務，發現了事故期間存在大量的資料庫慢查詢。  上述慢查詢來自於事故期間一個剛上線的大資料抽取任務，從扣費服務的mysql資料庫中大批量併發抽取資料到hive表。因為扣費流程也涉及到寫mysql，猜測這個時候mysql的所有讀寫效能都受到了影響，果然進一步發現insert操作的耗時也遠遠大於正常時期。  **第3步**：我們猜測資料庫慢查詢影響了扣費流程的效能，從而造成了任務佇列的積壓，所以決定立馬暫定大資料抽取任務。但是很奇怪：停止抽取任務後，資料庫的insert效能恢復到正常水平了，但是阻塞佇列大小仍然還在持續增大，告警並未消失。 **第4步**：考慮廣告收入還在持續大幅度下跌，進一步分析程式碼需要比較長的時間，所以決定立即重啟服務看看有沒有效果。為了保留事故現場，我們保留了一臺伺服器未做重啟，只是把這臺機器從服務管理平臺摘掉了，這樣它不會接收到新的扣費請求。 果然重啟服務的殺手鐗很管用，各項業務指標都恢復正常了，告警也沒有再出現。至此，整個線上故障得到解決，持續了大概30分鐘。
### **04 問題根本原因的分析過程** 下面再詳細說下事故根本原因的分析過程。 **第1步**：第二天上班後，我們猜測那臺保留了事故現場的伺服器，佇列中積壓的任務應該都被執行緒池處理掉了，所以嘗試把這臺伺服器再次掛載上去驗證下我們的猜測，結果和預期完全相反，積壓的任務仍然都在，而且隨著新請求進來，系統告警立刻再次出現了，所以又馬上把這臺伺服器摘了下來。 **第2步**：執行緒池積壓的幾千個任務，經過1個晚上都沒被執行緒池處理掉，我們猜測應該存在死鎖情況。所以打算通過jstack命令dump執行緒快照做下詳細分析。 ``` #找到扣費服務的程序號 $ ps aux|grep "adclick" # 通過程序號dump執行緒快照，輸出到檔案中 $ jstack pid > /tmp/stack.txth ``` 在jstack的日誌檔案中，立馬發現了：用於扣費的業務執行緒池的所有執行緒都處於waiting狀態，執行緒全部卡在了截圖中紅框部分對應的程式碼行上，這行程式碼呼叫了countDownLatch的await()方法，即等待計數器變為0後釋放共享鎖。 
**第3步**：找到上述異常後，距離找到根本原因就很接近了，我們回到程式碼中繼續調查，首先看了下業務程式碼中使用了newFixedThreadPool執行緒池，核心執行緒數設定為25。針對newFixedThreadPool，JDK文件的說明如下： > 建立一個可重用固定執行緒數的執行緒池，以共享的無界佇列方式來執行這些執行緒。如果在所有執行緒處於活躍狀態時提交新任務，則在有可用執行緒之前，新任務將在佇列中等待。 關於newFixedThreadPool，核心包括兩點： > 1、最大執行緒數 = 核心執行緒數，當所有核心執行緒都在處理任務時，新進來的任務會提交到任務佇列中等待； > > 2、使用了無界佇列：提交給執行緒池的任務佇列是不限制大小的，如果任務被阻塞或者處理變慢，那麼顯然佇列會越來越大。 所以，進一步結論是：核心執行緒全部死鎖，新進的任務不對湧入無界佇列，導致任務佇列不斷增加。
**第4步**：到底是什麼原因導致的死鎖，我們再次回到jstack日誌檔案中提示的那行程式碼做進一步分析。下面是我簡化過後的示例程式碼： ``` /*** 執行扣費任務 */ public Result
### **01 業務背景描述** 該線上問題發生在廣告系統的核心扣費服務，首先簡單交代下大致的業務流程，方便理解問題。  綠框部分即扣費服務在廣告召回扣費流程中所處的位置，簡單理解：當用戶點選一個廣告後，會從C端發起一次實時扣費請求(CPC，按點選扣費模式)，扣費服務則承接了該動作的核心業務邏輯：包括執行反作弊策略、建立扣費記錄、click日誌埋點等。
### **02 問題現象和業務影響** 12月2號晚上11點左右，我們收到了一個線上告警通知：扣費服務的執行緒池任務佇列大小遠遠超出了設定閾值，而且佇列大小隨著時間推移還在持續變大。詳細告警內容如下： 
相應的，我們的廣告指標：點選數、收入等也出現了非常明顯的下滑，幾乎同時發出了業務告警通知。其中，點選數指標對應的曲線表現如下：  該線上故障發生在流量高峰期，持續了將近30分鐘後才恢復正常。
### **03 問題調查和事故解決過程** 下面詳細說下整個事故的調查和分析過程。 **第1步**：收到執行緒池任務佇列的告警後，我們第一時間查看了扣費服務各個維度的實時資料：包括服務呼叫量、超時量、錯誤日誌、JVM監控，均未發現異常。 **第2步**：然後進一步排查了扣費服務依賴的儲存資源（mysql、redis、mq），外部服務，發現了事故期間存在大量的資料庫慢查詢。  上述慢查詢來自於事故期間一個剛上線的大資料抽取任務，從扣費服務的mysql資料庫中大批量併發抽取資料到hive表。因為扣費流程也涉及到寫mysql，猜測這個時候mysql的所有讀寫效能都受到了影響，果然進一步發現insert操作的耗時也遠遠大於正常時期。  **第3步**：我們猜測資料庫慢查詢影響了扣費流程的效能，從而造成了任務佇列的積壓，所以決定立馬暫定大資料抽取任務。但是很奇怪：停止抽取任務後，資料庫的insert效能恢復到正常水平了，但是阻塞佇列大小仍然還在持續增大，告警並未消失。 **第4步**：考慮廣告收入還在持續大幅度下跌，進一步分析程式碼需要比較長的時間，所以決定立即重啟服務看看有沒有效果。為了保留事故現場，我們保留了一臺伺服器未做重啟，只是把這臺機器從服務管理平臺摘掉了，這樣它不會接收到新的扣費請求。 果然重啟服務的殺手鐗很管用，各項業務指標都恢復正常了，告警也沒有再出現。至此，整個線上故障得到解決，持續了大概30分鐘。
### **04 問題根本原因的分析過程** 下面再詳細說下事故根本原因的分析過程。 **第1步**：第二天上班後，我們猜測那臺保留了事故現場的伺服器，佇列中積壓的任務應該都被執行緒池處理掉了，所以嘗試把這臺伺服器再次掛載上去驗證下我們的猜測，結果和預期完全相反，積壓的任務仍然都在，而且隨著新請求進來，系統告警立刻再次出現了，所以又馬上把這臺伺服器摘了下來。 **第2步**：執行緒池積壓的幾千個任務，經過1個晚上都沒被執行緒池處理掉，我們猜測應該存在死鎖情況。所以打算通過jstack命令dump執行緒快照做下詳細分析。 ``` #找到扣費服務的程序號 $ ps aux|grep "adclick" # 通過程序號dump執行緒快照，輸出到檔案中 $ jstack pid > /tmp/stack.txth ``` 在jstack的日誌檔案中，立馬發現了：用於扣費的業務執行緒池的所有執行緒都處於waiting狀態，執行緒全部卡在了截圖中紅框部分對應的程式碼行上，這行程式碼呼叫了countDownLatch的await()方法，即等待計數器變為0後釋放共享鎖。 
**第3步**：找到上述異常後，距離找到根本原因就很接近了，我們回到程式碼中繼續調查，首先看了下業務程式碼中使用了newFixedThreadPool執行緒池，核心執行緒數設定為25。針對newFixedThreadPool，JDK文件的說明如下： > 建立一個可重用固定執行緒數的執行緒池，以共享的無界佇列方式來執行這些執行緒。如果在所有執行緒處於活躍狀態時提交新任務，則在有可用執行緒之前，新任務將在佇列中等待。 關於newFixedThreadPool，核心包括兩點： > 1、最大執行緒數 = 核心執行緒數，當所有核心執行緒都在處理任務時，新進來的任務會提交到任務佇列中等待； > > 2、使用了無界佇列：提交給執行緒池的任務佇列是不限制大小的，如果任務被阻塞或者處理變慢，那麼顯然佇列會越來越大。 所以，進一步結論是：核心執行緒全部死鎖，新進的任務不對湧入無界佇列，導致任務佇列不斷增加。
**第4步**：到底是什麼原因導致的死鎖，我們再次回到jstack日誌檔案中提示的那行程式碼做進一步分析。下面是我簡化過後的示例程式碼： ``` /*** 執行扣費任務 */ public Result