線上故障複盤｜RPC 執行緒池被打滿，1024個執行緒居然不夠用？

1. 故障背景

昨天晚上，我剛到家裡打開公司群，就看見群組裡有人討論：線上環境出現大量RPC請求報錯，異常原因：被線程池拒絕。雖然異常量很大，但是異常服務非核心服務，屬於系統旁路，服務於資料核對任務，即使有大量異常，也沒有實際的影響。

原來有人在線上刷數據，產生了大量binlog，資料核對任務的請求量大幅上漲，導致線程池被打滿。因為並非我負責的工作內容，也不熟悉這部分業務，所以沒有特別留意。

第二天我仔細思考了一下，覺得疑點很多，推導過程過於簡單，證據鏈不足，最終結論不紮實，問題根源也許另有原因。

1.1 疑點

• 請求量大幅上漲， 上漲前後請求量是多少？
• 執行緒池被打滿， 執行緒池初始值和最大值是多少，執行緒池佇列長度是多少？
• 執行緒池拒絕策略是什麼？
• 影響了哪些接口，這些接口的耗時波動情況？
• 服務的CPU 負載和GC情況如何？
• 線程池被打滿的原因只是請求量大幅上漲嗎？

帶著以上的幾點疑問，隔天一到公司，我就迫不及待地打開各種監控大盤，開始排查問題，最後還真叫我揪出問題根源了。

因為公司的監控系統有浮水印，所以我只能陳述結論，不能截圖了。

2. 排查過程

2.1 請求量的波動情況

• 單機RPC的QPS從300/s 漲到了450/s。
• Kafka 訊息QPS 50/s 無明顯波動。
• 無其他請求入口和無定時任務。

這也能叫請求量大幅上漲，請求量增加150/s 能打爆線程池？就這麼糊弄老闆…… ，由此我堅定了判斷：故障另有根因

2.2 RPC 執行緒池配置與監控

線上的連接埠並沒有全部被打爆，只有1 個RPC 連接埠8001 被打爆。所以我特地查看了8001 的線程池配置。

• 初始線程數10
• 最大執行緒數1024（數量過大，配置的有點隨意了）
• 佇列長度 0
• 拒絕策略是拋出異常立即拒絕。
• 在20:11到20:13 分，線程從初始線程數10，直線漲到了1024 。

2.3 思考

QPS 450次/秒需要1024 個執行緒處理嗎？依照我的經驗來看，只要介面的耗時在100ms 以內，不可能需要這麼多的線程，太蹊蹺了。

2.4 接口耗時波動狀況

介面平均耗時從5.7 ms，增加到17000毫秒。

接口耗時大幅增加。後來和他們溝通，當時也看了介面耗時監控。他們認為之所以平均耗時這麼高，是因為RPC 請求在排隊，增加了處理耗時，所以監控平均耗時大幅成長。

這是他們的誤區，錯誤的地方有兩個。

• 此RPC介面執行緒池的佇列長度為0，拒絕策略是拋出例外。當沒有可用線程，請求會即被拒絕，請求不會排隊，所以無排隊等待時間。
• 本公司的監控系統分服務端監控與呼叫端監控，服務端的耗時監控不包含處理連線的時間，不包含RPC執行緒池排隊的時間。只是RPC 執行緒池實際處理請求的耗時。 RPC 呼叫端的監控包含RPC 網路耗時、連線耗時、排隊耗時、處理業務邏輯耗時、服務端GC 耗時等等。

他們誤認為耗時大幅增加是因為請求在排隊，因此忽略了至關重要的這條線索：介面實際處理階段的效能嚴重惡化，吞吐量大幅降低，所以執行緒池大幅成長，直到被打滿。

接下來我開始分析，介面效能惡化的根本原因是什麼？

• CPU 被打滿？導致請求介面效能惡化？
• 頻繁GC ，導致介面性能差？
• 呼叫下游RPC 介面耗時大幅增加？
• 調用SQL，耗時大幅增加？
• 呼叫Redis，耗時大幅增加
• 其他外部呼叫耗時大幅增加？

2.5 其他耗時監控狀況

我快速的排查了所有可能的外部呼叫耗時均沒有明顯波動。也查看了機器的負載情況，cpu和網路負載均不高，顯然故障的根源不在以上方向。

• CPU 負載極低。在故障期間，cpu.busy 負載在15%，還不到午高峰，顯然根源不是CPU 負載高。
• gc 情況良好。無FullGC，youngGC 1 分鐘2 次（younggc 頻繁，會導致cpu 負載高，會使介面效能惡化）
• 下游RPC 介面耗時無明顯波動。我查看了服務呼叫RPC 介面的耗時監控，所有的介面耗時無明顯波動。
• SQL 呼叫耗時無明顯波動。
• 呼叫Redis 耗時無明顯波動。
• 其他下游系統調用無明顯波動。 （如Tair、ES 等）

2.6 開始研究程式碼

為什麼我一開始不看程式碼，因為這塊內容不是我負責的內容，我不熟悉程式碼。

直到打開代碼看了一眼，噁心死我了。程式碼非常複雜，分支非常多，嵌套層次非常深，方法又臭又長，堪稱代碼屎山的珠穆朗瑪峰，多看一眼就能吐。介面的內部分支將近10 個，每個分支方法都是一大塊程式碼。

這個接口是上游BCP 核對系統定義的SPI接口，屬於聚合接口，並非單一職責的接口。看了10 分鐘以後，還是找不到問題根源。因此我換了問題排查方向，我開始檢視異常Trace。

2.7 從異常Trace 發現了關鍵線索

我所在公司的基礎建設能力還是很強大的。系統的異常Trace 中標註了各個階段的處理耗時，包括所有外部介面的耗時。如SQL、 RPC、 Redis等。

我發現確實是內部程式碼處理的問題，因為trace 顯示，在兩個SQL 請求中間，系統停頓長達1 秒以上。不知道系統在這1 秒執行哪些內容。我查看了這兩個介面的耗時，監控顯示：SQL 執行很快，應該不是SQL 的問題

機器也沒有發生FullGC，到底是什麼原因？

前面提到，故障接口是一個聚合接口，我不清楚具體哪個分支出現了問題，但是異常Trace 中指明了具體的分支。

我開始排查具體的分支方法…， 然而捏著鼻子扒拉了半天，也沒有找到原因…

2.8 山窮水復疑無路，柳暗花明又一村

這坨屎山代碼看得我實在噁心，我靜靜地冥想了1 分鐘才緩過勁。

• 沒有外部呼叫的情況下，阻塞執行緒的可能性有哪些？
• 有沒有加鎖? Synchiozed 關鍵字？

於是我按著關鍵字搜尋Synchiozed關鍵字，一無所獲，程式碼中基本上沒有加鎖的地方。

馬上中午了，肚子很餓，就當我要放棄的時候。隨手扒拉了一下，在類別的屬性聲明裡，看到了Guava限流器。

激動的心，顫抖的手

1. private static final RateLimiter RATE_LIMITER = RateLimiter.create(10, 20, TimeUnit.SECONDS);

限流器：1 分鐘10次呼叫。

於是立即查看限流器的使用場景，和異常Trace 阻斷的地方完全一致。

嘴角出現一絲很容易察覺的微笑。

破案了，真相永遠只有一個。

3. 問題結論

Guava 限流器的閾值過低，每秒最大請求量只有10次。當並發量超過這個閾值時，大量執行緒被阻塞，RPC執行緒池不斷增加新執行緒來處理新的請求，直到達到最大執行緒數。線程池達到最大容量後，無法再接收新的請求，導致大量的後續請求被線程池拒絕。

於是我開始建群、搖人。把相關的同學，還有老闆們，拉進了群組。把相關截圖和結論發到群組了。

由於不是緊急問題，所以我開開心心的去吃午餐了。後面的事就是他們優化程式碼了。

出現問題不要慌張，也不要吃瓜嗑瓜子。行動起來，此時是專屬你的柯南時刻