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限流器。

激動的心，顫抖的手

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

限流器：1 分鐘 10次調用。

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

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

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

3. 問題結論

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

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

由于不是緊急問題，所以我開開心心的去吃午飯了。后面的事就是他們優化代碼了。

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