1. 故障背景

昨天晚上，我剛到家里打開(kāi)公司群，就看見(jiàn)群里有人討論：線上環(huán)境出現(xiàn)大量RPC請(qǐng)求報(bào)錯(cuò)，異常原因：被線程池拒絕。雖然異常量很大，但是異常服務(wù)非核心服務(wù)，屬于系統(tǒng)旁路，服務(wù)于數(shù)據(jù)核對(duì)任務(wù)，即使有大量異常，也沒(méi)有實(shí)際的影響。

原來(lái)有人在線上刷數(shù)據(jù)，產(chǎn)生了大量 binlog，數(shù)據(jù)核對(duì)任務(wù)的請(qǐng)求量大幅上漲，導(dǎo)致線程池被打滿。因?yàn)椴⒎俏邑?fù)責(zé)的工作內(nèi)容，也不熟悉這部分業(yè)務(wù)，所以沒(méi)有特別留意。

第二天我仔細(xì)思考了一下，覺(jué)得疑點(diǎn)很多，推導(dǎo)過(guò)程過(guò)于簡(jiǎn)單，證據(jù)鏈不足，最終結(jié)論不扎實(shí)，問(wèn)題根源也許另有原因。

1.1 疑點(diǎn)

• 請(qǐng)求量大幅上漲， 上漲前后請(qǐng)求量是多少？
• 線程池被打滿， 線程池初始值和最大值是多少，線程池隊(duì)列長(zhǎng)度是多少？
• 線程池拒絕策略是什么？
• 影響了哪些接口，這些接口的耗時(shí)波動(dòng)情況？
• 服務(wù)的 CPU 負(fù)載和 GC情況如何？
• 線程池被打滿的原因僅僅是請(qǐng)求量大幅上漲嗎？

帶著以上的幾點(diǎn)疑問(wèn)，第二天一到公司，我就迫不及待地打開(kāi)各種監(jiān)控大盤(pán)，開(kāi)始排查問(wèn)題，最后還真叫我揪出問(wèn)題根源了。

因?yàn)楣镜谋O(jiān)控系統(tǒng)有水印，所以我只能陳述結(jié)論，不能截圖了。

2. 排查過(guò)程

2.1 請(qǐng)求量的波動(dòng)情況

• 單機(jī) RPC的 QPS從 300/s 漲到了 450/s。
• Kafka 消息 QPS 50/s 無(wú) 明顯波動(dòng)。
• 無(wú)其他請(qǐng)求入口和 無(wú)定時(shí)任務(wù)。

這也能叫請(qǐng)求量大幅上漲，請(qǐng)求量增加 150/s 能打爆線程池？就這么糊弄老板…… ，由此我堅(jiān)定了判斷：故障另有根因

2.2 RPC 線程池配置和監(jiān)控

線上的端口并沒(méi)有全部被打爆，僅有 1 個(gè) RPC 端口 8001 被打爆。所以我特地查看了8001 的線程池配置。

• 初始線程數(shù) 10
• 最大線程數(shù) 1024（數(shù)量過(guò)大，配置的有點(diǎn)隨意了）
• 隊(duì)列長(zhǎng)度 0
• 拒絕策略是拋出異常立即拒絕。
• 在 20:11到 20:13 分，線程從初始線程數(shù)10，直線漲到了1024 。

2.3 思考

QPS 450次/秒 需要 1024 個(gè)線程處理嗎？按照我的經(jīng)驗(yàn)來(lái)看，只要接口的耗時(shí)在 100ms 以內(nèi)，不可能需要如此多的線程，太蹊蹺了。

2.4 接口耗時(shí)波動(dòng)情況

接口 平均耗時(shí)從 5.7 ms，增加到 17000毫秒。

接口耗時(shí)大幅增加。后來(lái)和他們溝通，他們當(dāng)時(shí)也看了接口耗時(shí)監(jiān)控。他們認(rèn)為之所以平均耗時(shí)這么高，是因?yàn)镽PC 請(qǐng)求在排隊(duì)，增加了處理耗時(shí)，所以監(jiān)控平均耗時(shí)大幅增長(zhǎng)。

這是他們的誤區(qū)，錯(cuò)誤的地方有兩個(gè)。

• 此RPC接口線程池的隊(duì)列長(zhǎng)度為 0，拒絕策略是拋出異常。當(dāng)沒(méi)有可用線程，請(qǐng)求會(huì)即被拒絕，請(qǐng)求不會(huì)排隊(duì)，所以無(wú)排隊(duì)等待時(shí)間。
• 公司的監(jiān)控系統(tǒng)分服務(wù)端監(jiān)控和調(diào)用端監(jiān)控，服務(wù)端的耗時(shí)監(jiān)控不包含 處理連接的時(shí)間，不包含 RPC線程池排隊(duì)的時(shí)間。僅僅是 RPC 線程池實(shí)際處理請(qǐng)求的耗時(shí)。RPC 調(diào)用端的監(jiān)控包含 RPC 網(wǎng)絡(luò)耗時(shí)、連接耗時(shí)、排隊(duì)耗時(shí)、處理業(yè)務(wù)邏輯耗時(shí)、服務(wù)端GC 耗時(shí)等等。

他們誤認(rèn)為耗時(shí)大幅增加是因?yàn)檎?qǐng)求在排隊(duì)，因此忽略了至關(guān)重要的這條線索：接口實(shí)際處理階段的性能?chē)?yán)重惡化，吞吐量大幅降低，所以線程池大幅增長(zhǎng)，直至被打滿。

接下來(lái)我開(kāi)始分析，接口性能惡化的根本原因是什么？

• CPU 被打滿？導(dǎo)致請(qǐng)求接口性能惡化？
• 頻繁GC ，導(dǎo)致接口性能差？
• 調(diào)用下游 RPC 接口耗時(shí)大幅增加 ？
• 調(diào)用 SQL，耗時(shí)大幅增加？
• 調(diào)用 Redis，耗時(shí)大幅增加
• 其他外部調(diào)用耗時(shí)大幅增加？

2.5 其他耗時(shí)監(jiān)控情況

我快速的排查了所有可能的外部調(diào)用耗時(shí)均沒(méi)有明顯波動(dòng)。也查看了機(jī)器的負(fù)載情況，cpu和網(wǎng)絡(luò)負(fù)載 均不高，顯然故障的根源不在以上方向。

• CPU 負(fù)載極低。在故障期間，cpu.busy 負(fù)載在 15%，還不到午高峰，顯然根源不是CPU 負(fù)載高。
• gc 情況良好。無(wú) FullGC，youngGC 1 分鐘 2 次（younggc 頻繁，會(huì)導(dǎo)致 cpu 負(fù)載高，會(huì)使接口性能惡化）
• 下游 RPC 接口耗時(shí)無(wú)明顯波動(dòng)。我查看了服務(wù)調(diào)用 RPC 接口的耗時(shí)監(jiān)控，所有的接口耗時(shí)無(wú)明顯波動(dòng)。
• SQL 調(diào)用耗時(shí)無(wú)明顯波動(dòng)。
• 調(diào)用 Redis 耗時(shí)無(wú)明顯波動(dòng)。
• 其他下游系統(tǒng)調(diào)用無(wú)明顯波動(dòng)。（如 Tair、ES 等）

2.6 開(kāi)始研究代碼

為什么我一開(kāi)始不看代碼，因?yàn)檫@塊內(nèi)容不是我負(fù)責(zé)的內(nèi)容，我不熟悉代碼。

直至打開(kāi)代碼看了一眼，惡心死我了。代碼非常復(fù)雜，分支非常多，嵌套層次非常深，方法又臭又長(zhǎng)，堪稱代碼屎山的珠穆朗瑪峰，多看一眼就能吐。接口的內(nèi)部分支將近 10 個(gè)，每個(gè)分支方法都是一大坨代碼。

這個(gè)接口是上游 BCP 核對(duì)系統(tǒng)定義的 SPI接口，屬于聚合接口，并非單一職責(zé)的接口。看了 10 分鐘以后，還是找不到問(wèn)題根源。因此我換了問(wèn)題排查方向，我開(kāi)始排查異常 Trace。

2.7 從異常 Trace 發(fā)現(xiàn)了關(guān)鍵線索

我所在公司的基建能力還是很強(qiáng)大的。系統(tǒng)的異常 Trace 中標(biāo)注了各個(gè)階段的處理耗時(shí)，包括所有外部接口的耗時(shí)。如SQL、 RPC、 Redis等。

我發(fā)現(xiàn)確實(shí)是內(nèi)部代碼處理的問(wèn)題，因?yàn)?trace 顯示，在兩個(gè) SQL 請(qǐng)求中間，系統(tǒng)停頓長(zhǎng)達(dá) 1 秒多。不知道系統(tǒng)在這 1 秒執(zhí)行哪些內(nèi)容。我查看了這兩個(gè)接口的耗時(shí)，監(jiān)控顯示：SQL 執(zhí)行很快，應(yīng)該不是SQL 的問(wèn)題

機(jī)器也沒(méi)有發(fā)生 FullGC，到底是什么原因呢？

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

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

2.8 山窮水復(fù)疑無(wú)路，柳暗花明又一村

這一坨屎山代碼看得我實(shí)在惡心，我靜靜地冥想了 1 分鐘才緩過(guò)勁。

• 沒(méi)有外部調(diào)用的情況下，阻塞線程的可能性有哪些？
• 有沒(méi)有加鎖? Synchiozed 關(guān)鍵字？

于是我按著關(guān)鍵字搜索Synchiozed關(guān)鍵詞，一無(wú)所獲，代碼中基本沒(méi)有加鎖的地方。

馬上中午了，肚子很餓，就當(dāng)我要放棄的時(shí)候。隨手扒拉了一下，在類的屬性聲明里，看到了 Guava限流器。

激動(dòng)的心，顫抖的手

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

限流器：1 分鐘 10次調(diào)用。

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

嘴角出現(xiàn)一絲很容易察覺(jué)到的微笑。

破案了，真相永遠(yuǎn)只有一個(gè)。

3. 問(wèn)題結(jié)論

Guava 限流器的閾值過(guò)低，每秒最大請(qǐng)求量只有10次。當(dāng)并發(fā)量超過(guò)這個(gè)閾值時(shí)，大量線程被阻塞，RPC線程池不斷增加新線程來(lái)處理新的請(qǐng)求，直到達(dá)到最大線程數(shù)。線程池達(dá)到最大容量后，無(wú)法再接收新的請(qǐng)求，導(dǎo)致大量的后續(xù)請(qǐng)求被線程池拒絕。

于是我開(kāi)始建群、搖人。把相關(guān)的同學(xué)，還有老板們，拉進(jìn)了群里。把相關(guān)截圖和結(jié)論發(fā)到了群里。

由于不是緊急問(wèn)題，所以我開(kāi)開(kāi)心心的去吃午飯了。后面的事就是他們優(yōu)化代碼了。

出現(xiàn)問(wèn)題不要慌張，也不要吃瓜嗑瓜子。行動(dòng)起來(lái)，此時(shí)是專屬你的柯南時(shí)刻