本文已收錄 https://github.com/lkxiaolou/lkxiaolou 歡迎star。搜尋關注微信公眾號"捉蟲大師",後端技術分享,架構設計、效能優化、原始碼閱讀、問題排查、踩坑實踐。

背景

最近某天的深夜,剛洗完澡就接到業務方打來電話,說他們的 dubbo 服務出故障了,要我協助排查一下。

電話裡,詢問了他們幾點

  • 是線上有損故障嗎?——是
  • 止損了嗎?——止損了
  • 有保留現場嗎?——沒有

於是我開啟電腦,連上 VPN 看問題。為了便於理解,架構簡化如下

只需要關注 A、B、C 三個服務,他們之間呼叫都是 dubbo 呼叫。

發生故障時 B 服務有幾臺機器完全夯死,處理不了請求,剩餘正常機器請求量激增,耗時增加,如下圖(圖一請求量、圖二耗時)

問題排查

由於現場已被破壞,只能先看監控和日誌

  • 監控

除了上述監控外,翻看了 B 服務 CPU 和記憶體等基礎監控,發現故障的幾臺機器記憶體上漲比較多,都達到了 80% 的水平線,且 CPU 消耗也變多

這時比較懷疑記憶體問題,於是看了下 JVM 的 fullGC 監控

果然 fullGC 時間上漲很多,基本可以斷定是記憶體洩漏導致服務不可用了。但為什麼會記憶體洩漏,還無法看出端倪。

  • 日誌

申請機器許可權,檢視日誌,發現了一條很奇怪的 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]

可以看出業務方使用的是2.7.12版本的 dubbo

拿這個日誌去 dubbo 的 github 倉庫搜了一下,找到了如下這個 issue:

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

但很快排除了該問題,因為在 2.7.12 版本中已經是修復過的程式碼了。

繼續又找到了這兩個 issue:

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

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

從報錯和版本上來看,完全符合,但沒有提及記憶體問題,先不管記憶體問題,看看是否可以按照 #8188 這個 issue 復現

issue中也說的比較清楚如何復現,於是我搭了這樣三個服務來複現,剛開始還沒有復現。通過修復程式碼來反推

刪除程式碼部分是有問題,但我們復現卻難以進入這塊,怎麼才能進入呢?

這裡一個 feature 代表一個請求,只有當請求沒有完成時才會進入,這就好辦了,讓 provider 一直不返回,肯定可以實現,於是在provider 端測試程式碼加入

Thread.sleep(Integer.MAX_VALUE);

經過測試果然復現了,如 issue 所說,當 kill -9 掉第一個 provider 時,消費者全域性 ExecutorService 被關閉,當 kill -9 第二個 provider 時,SHARED_EXECUTOR 也被關閉。

那麼這個執行緒池是用來幹什麼的呢?

它在 HashedWheelTimer 中被用來檢測 consumer 發出的請求是否超時。

HashedWheelTimer 是 dubbo 實現的一種時間輪檢測請求是否超時的演算法,具體這裡不再展開,改天可以詳細寫一篇 dubbo 中時間輪演算法。

當請求發出後,如果可以正常返回還好,但如果超過設定的超時時間還未返回,則需要這個執行緒池的任務來檢測,對已經超時的任務進行打斷。

如下程式碼為提交任務,當這個執行緒池被關閉後,提交任務就會丟擲異常,超時也就無法檢測。

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);
}
}
}

到這裡恍然大悟:如果請求一直髮送,不超時,那是不是有可能撐爆記憶體?於是我又模擬了一下,並且開了 3 個執行緒一直請求 provider,果然復現出記憶體被撐爆的場景,而當不觸發這個問題時,記憶體是一直穩定在一個低水平上。

這裡我用的 arthas 來看的記憶體變化,非常方便

得出結論

在本地復現後,於是跟業務方求證一下,這個問題復現還是比較苛刻的,首先得是非同步呼叫,其次 provider 需要非正常下線,最後 provider 需要有阻塞,即請求一直不返回。

非同步呼叫得到業務方的確認,provider 非正常下線,這個比較常見,物理機的故障導致的容器漂移就會出現這個情況,最後 provider 有阻塞這點也得到業務方的確認,確實 C 服務有一臺機器在那個時間點附近僵死,無法處理請求,但程序又是存活的。

所以這個問題是 dubbo 2.7.12 的 bug 導致。翻看了下這個 bug 是 2.7.10 引入, 2.7.13 修復。

覆盤

差不多花了1天的時間來定位和復現,還算順利,運氣也比較好,沒怎麼走彎路,但這中間也需要有些地方需要引起重視。

  • 止損的同時最好能保留現場,如本次如果在重啟前 dump 下記憶體或摘除流量保留機器現場,可能會幫助加速定位問題。如配置 OOM 時自動 dump 記憶體等其他手段。這也是本起事故中不足的點
  • 服務的可觀測性非常重要,不管是日誌、監控或其他,都要齊全。基本的如日誌、出口、進口請求監控、機器指標(記憶體、CPU、網路等)、JVM 監控(執行緒池、GC 等)。這點做的還可以,基本該有的都有
  • 開源產品,可從關鍵日誌去網路查詢,極大概率你遇到的問題大家也遇到過。這也是這次幸運的點,少走了很多彎路

搜尋關注微信公眾號"捉蟲大師",後端技術分享,架構設計、效能優化、原始碼閱讀、問題排查、踩坑實踐。