本文轉(zhuǎn)載自微信公眾號(hào)「捉蟲(chóng)大師」，作者捉蟲(chóng)大師。轉(zhuǎn)載本文請(qǐng)聯(lián)系捉蟲(chóng)大師公眾號(hào)。

背景

最近某天的深夜，剛洗完澡就接到業(yè)務(wù)方打來(lái)電話，說(shuō)他們的 dubbo 服務(wù)出故障了，要我協(xié)助排查一下。

電話里，詢問(wèn)了他們幾點(diǎn)

• 是線上有損故障嗎?——是
• 止損了嗎?——止損了
• 有保留現(xiàn)場(chǎng)嗎?——沒(méi)有

于是我打開(kāi)電腦，連上 網(wǎng)絡(luò)看問(wèn)題。為了便于理解，架構(gòu)簡(jiǎn)化如下

只需要關(guān)注 A、B、C 三個(gè)服務(wù)，他們之間調(diào)用都是 dubbo 調(diào)用。

發(fā)生故障時(shí) B 服務(wù)有幾臺(tái)機(jī)器完全夯死，處理不了請(qǐng)求，剩余正常機(jī)器請(qǐng)求量激增，耗時(shí)增加，如下圖(圖一請(qǐng)求量、圖二耗時(shí))

問(wèn)題排查

由于現(xiàn)場(chǎng)已被破壞，只能先看監(jiān)控和日志

• 監(jiān)控

除了上述監(jiān)控外，翻看了 B 服務(wù) CPU 和內(nèi)存等基礎(chǔ)監(jiān)控，發(fā)現(xiàn)故障的幾臺(tái)機(jī)器內(nèi)存上漲比較多，都達(dá)到了 80% 的水平線，且 CPU 消耗也變多

這時(shí)比較懷疑內(nèi)存問(wèn)題，于是看了下 JVM 的 fullGC 監(jiān)控

果然 fullGC 時(shí)間上漲很多，基本可以斷定是內(nèi)存泄漏導(dǎo)致服務(wù)不可用了。但為什么會(huì)內(nèi)存泄漏，還無(wú)法看出端倪。

• 日志

申請(qǐng)機(jī)器權(quán)限，查看日志，發(fā)現(xiàn)了一條很奇怪的 WARN 日志

[dubbo-future-timeout-thread-1] WARN org.apache.dubbo.common.timer.HashedWheelTimer$HashedWheelTimeout 
(HashedWheelTimer.java:651)  
-  [DUBBO] An exception was thrown by TimerTask., dubbo version: 2.7.12, current host: xxx.xxx.xxx.xxx 
java.util.concurrent.RejectedExecutionException:  
Task org.apache.dubbo.remoting.exchange.support.DefaultFuture$TimeoutCheckTask$$Lambda$674/1067077932@13762d5a  
rejected from java.util.concurrent.ThreadPoolExecutor@7a9f0e84[Terminated, pool size = 0,  
active threads = 0, queued tasks = 0, completed tasks = 21] 

可以看出業(yè)務(wù)方使用的是2.7.12版本的 dubbo

拿這個(gè)日志去 dubbo 的 github 倉(cāng)庫(kù)搜了一下，找到了如下這個(gè) issue：

https://github.com/apache/dubbo/issues/6820

但很快排除了該問(wèn)題，因?yàn)樵?2.7.12 版本中已經(jīng)是修復(fù)過(guò)的代碼了。

繼續(xù)又找到了這兩個(gè) issue：

https://github.com/apache/dubbo/issues/8172

https://github.com/apache/dubbo/pull/8188

從報(bào)錯(cuò)和版本上來(lái)看，完全符合，但沒(méi)有提及內(nèi)存問(wèn)題，先不管內(nèi)存問(wèn)題，看看是否可以按照 #8188 這個(gè) issue 復(fù)現(xiàn)

issue 中也說(shuō)的比較清楚如何復(fù)現(xiàn)，于是我搭了這樣三個(gè)服務(wù)來(lái)復(fù)現(xiàn)，剛開(kāi)始還沒(méi)有復(fù)現(xiàn)。通過(guò)修復(fù)代碼來(lái)反推

刪除代碼部分是有問(wèn)題，但我們復(fù)現(xiàn)卻難以進(jìn)入這塊，怎么才能進(jìn)入呢?

這里一個(gè) feature 代表一個(gè)請(qǐng)求，只有當(dāng)請(qǐng)求沒(méi)有完成時(shí)才會(huì)進(jìn)入，這就好辦了，讓 provider 一直不返回，肯定可以實(shí)現(xiàn)，于是在 provider 端測(cè)試代碼加入

Thread.sleep(Integer.MAX_VALUE); 

經(jīng)過(guò)測(cè)試果然復(fù)現(xiàn)了，如 issue 所說(shuō)，當(dāng) kill -9 掉第一個(gè) provider 時(shí)，消費(fèi)者全局 ExecutorService 被關(guān)閉，當(dāng) kill -9 第二個(gè) provider 時(shí)，SHARED_EXECUTOR 也被關(guān)閉。

那么這個(gè)線程池是用來(lái)干什么的呢?

它在 HashedWheelTimer 中被用來(lái)檢測(cè) consumer 發(fā)出的請(qǐng)求是否超時(shí)。

HashedWheelTimer 是 dubbo 實(shí)現(xiàn)的一種時(shí)間輪檢測(cè)請(qǐng)求是否超時(shí)的算法，具體這里不再展開(kāi)，改天可以詳細(xì)寫(xiě)一篇 dubbo 中時(shí)間輪算法。

當(dāng)請(qǐng)求發(fā)出后，如果可以正常返回還好，但如果超過(guò)設(shè)定的超時(shí)時(shí)間還未返回，則需要這個(gè)線程池的任務(wù)來(lái)檢測(cè)，對(duì)已經(jīng)超時(shí)的任務(wù)進(jìn)行打斷。

如下代碼為提交任務(wù)，當(dāng)這個(gè)線程池被關(guān)閉后，提交任務(wù)就會(huì)拋出異常，超時(shí)也就無(wú)法檢測(cè)。

public void expire() { 
    if (!compareAndSetState(ST_INIT, ST_EXPIRED)) { 
        return; 
    } 
    try { 
        task.run(this); 
    } catch (Throwable t) { 
        if (logger.isWarnEnabled()) { 
            logger.warn("An exception was thrown by " + TimerTask.class.getSimpleName() + '.', t); 
        } 
    } 
} 

到這里恍然大悟：如果請(qǐng)求一直發(fā)送，不超時(shí)，那是不是有可能撐爆內(nèi)存?于是我又模擬了一下，并且開(kāi)了 3 個(gè)線程一直請(qǐng)求 provider，果然復(fù)現(xiàn)出內(nèi)存被撐爆的場(chǎng)景，而當(dāng)不觸發(fā)這個(gè)問(wèn)題時(shí)，內(nèi)存是一直穩(wěn)定在一個(gè)低水平上。

這里我用的 arthas 來(lái)看的內(nèi)存變化，非常方便

得出結(jié)論

在本地復(fù)現(xiàn)后，于是跟業(yè)務(wù)方求證一下，這個(gè)問(wèn)題復(fù)現(xiàn)還是比較苛刻的，首先得是異步調(diào)用，其次 provider 需要非正常下線，最后 provider 需要有阻塞，即請(qǐng)求一直不返回。

異步調(diào)用得到業(yè)務(wù)方的確認(rèn)，provider 非正常下線，這個(gè)比較常見(jiàn)，物理機(jī)的故障導(dǎo)致的容器漂移就會(huì)出現(xiàn)這個(gè)情況，最后 provider 有阻塞這點(diǎn)也得到業(yè)務(wù)方的確認(rèn)，確實(shí) C 服務(wù)有一臺(tái)機(jī)器在那個(gè)時(shí)間點(diǎn)附近僵死，無(wú)法處理請(qǐng)求，但進(jìn)程又是存活的。

所以這個(gè)問(wèn)題是 dubbo 2.7.12 的 bug 導(dǎo)致。翻看了下這個(gè) bug 是 2.7.10 引入， 2.7.13 修復(fù)。

復(fù)盤(pán)

差不多花了1天的時(shí)間來(lái)定位和復(fù)現(xiàn)，還算順利，運(yùn)氣也比較好，沒(méi)怎么走彎路，但這中間也需要有些地方需要引起重視。

• 止損的同時(shí)最好能保留現(xiàn)場(chǎng)，如本次如果在重啟前 dump 下內(nèi)存或摘除流量保留機(jī)器現(xiàn)場(chǎng)，可能會(huì)幫助加速定位問(wèn)題。如配置 OOM 時(shí)自動(dòng) dump 內(nèi)存等其他手段。這也是本起事故中不足的點(diǎn)
• 服務(wù)的可觀測(cè)性非常重要，不管是日志、監(jiān)控或其他，都要齊全?；镜娜缛罩尽⒊隹?、進(jìn)口請(qǐng)求監(jiān)控、機(jī)器指標(biāo)(內(nèi)存、CPU、網(wǎng)絡(luò)等)、JVM 監(jiān)控(線程池、GC 等)。這點(diǎn)做的還可以，基本該有的都有
• 開(kāi)源產(chǎn)品，可從關(guān)鍵日志去網(wǎng)絡(luò)查找，極大概率你遇到的問(wèn)題大家也遇到過(guò)。這也是這次幸運(yùn)的點(diǎn)，少走了很多彎路