從一次Kafka當機說起（JVM hang）

一、背景

時間大概是在夏天7月份，突然收到小夥伴的情報，我們線上的一個kafka例項的某個broker突然不提供服務了，也沒看到什麼異常日誌，反正就是生產、消費都停了。因為是線上服務，而且程式還在，就是不提供服務了，第一反應就是保留一下 stack 資訊，先重啟吧

因為這個現象是第一次出現，不確定是哪裡的bug，作業系統、機器等都有可能。當時也沒重視這個問題，判斷可能是個偶發現象，broker重啟恢復後，因為業務繁忙，就把這事兒給擱置了

然而僅僅2個月後，這個問題又復現了，而且與上次出問題的機器不是同一臺，我知道這次沒法視而不見，可能要打一場硬仗了

下面是一些環境資訊

工程	版本
Kafka	2.8.2
JDK version	OpenJDK 1.8.0_312-b07
OS	linux
架構	aarch64
k8s	v1.18.8
golang	go1.13.15
Heap Size	24G
Java GC	G1

二、初探

與上次不同，這次透過多方協商，將現場出問題的pod保留了下來，這樣排查問題能夠主動一些。

2.1、日誌清除策略bug？

最先想到的就是記憶體洩露，讓現場的同學幫忙執行命令：jmap -histo [pid]，主要想看下每個類佔用空間的情況

首先感覺有問題的就是kafka.log.LogSegment的數量，達到了10萬+的數量，我們知道在kafka中，每個LogSegment例項就代表了一個日誌切片，然後現場的日誌保留時長是3天，怎麼可能會有這麼多檔案切片呢？

突然想到我們之前針對Kafka的檔案過期增加了一個新的feature：“即kafka檔案的總大小不能超過指定的閾值，如果超過的話，會將最老的檔案刪除”，難道這個feature存在未知bug，導致某些log沒有成功刪除？

def cleanupLogs(): Unit = {
  // 原kafka程式碼 begin
  ......
  ......
  // 原kafka程式碼 end

  total += cleanAllLogForSingleDisk()
  debug(s"Log cleanup completed. $total files deleted in " +
          (time.milliseconds - startMs) / 1000 + " seconds\n")
  debug(s"Log cleanup completed. $total files deleted in " +
          (time.milliseconds - startMs) / 1000 + " seconds")
}

// 新特性的入口
private def cleanAllLogForSingleDisk(): Int = {
  var totalSegmentsDeleted = 0
  logsByDir.values.foreach{ logs =>
    totalSegmentsDeleted += cleanLogSegmentsToFreeSpaceForDisk(logs)
  }
  totalSegmentsDeleted
}

基於kafka2.8.2新增這個特性中，只是在日誌清理執行緒的最後，判斷日誌空間是否超限，對原有的邏輯沒有侵入，而且也完全複用了kafka原生的清理邏輯，即將要刪除的.log、.timeinde、.index等檔案字尾新增.deleted。反覆review了這個特性的程式碼，整體邏輯應該是沒問題的

不對啊，那客戶當前broker的LogSegment怎麼會這麼大？後來發現客戶在broker部署使用了多檔案目錄結構，反覆確認了topic數量、partition數量後，證實使用者的LogSegment確實很多，雖然有效能上的一些問題，但並不是本地hang死的根源，因此需要切換思路

2.2、記憶體佔用分析

重新回到各個物件佔用空間上來，我將前幾名佔用空間比較大的類做了整理：

型別	個數	空間
byte[]	1099322	13913932672==13269M=12.9G
Double	49487382	1187697168/1024/1024==1132M=1.1G
ConcurrentSkipList	24375854	585020496/1024/1024=557M
char[]	296323392	296323392/1024/1024=282M

其實最大的還是byte[]，這個好理解，因為kafka後端儲存資料的時候，都是面向位元組儲存的，因此不論是網路執行緒還是IO執行緒，都會頻繁的在堆記憶體開闢空間 ByteBuffer.allocate()，然後很快可以在垃圾回收的時候被回收走，整體佔用情況還是比較正常的

好像這裡相對比較正常，沒有發現可疑之處。垃圾回收的日誌正常嗎？

2.3、垃圾回收日誌分析

目標機器的堆記憶體分配的很大，有足足24G的空間，之前遇到過大記憶體例項導致GC停頓很嚴重的case，會不會跟垃圾回收有關呢？但為了避免這種情況，已經為當前客戶例項啟用了G1，部分啟動命令如下

java -Xmx24576m -Xms24576m -server -XX:+UseG1GC 
-XX:MaxGCPauseMillis=20 
-XX:InitiatingHeapOccupancyPercent=35 
-XX:+ExplicitGCInvokesConcurrent 
-XX:MaxInlineLevel=15 

難道是配置GC停頓時長MaxGCPauseMillis=20過小的緣故？ G1中相對比較重要的一個引數了，用來控制Stop The World (STW) 的最大時長。檢查了一下歷史記錄，發現確實比較頻繁，基本上2~3秒就會觸發一次

又檢查了一下其他健康例項的GC情況，發現也類似，雖然這個配置項設定的有待商榷，但應該不是導致hang的根因

接著透過 jstat -gc [pid] 命令分析了下GC的歷史情況

原輸出沒有對齊，整理後如下：

EC	伊甸區總大小	15794176 = 15G
EU	伊甸區使用大小	15040512 = 14.3G
OC	老年代大小	9338880 = 8.9G
OU	老年代使用大小	6832518 = 6.5G
MC	方法區大小	79552 = 77M
MU	方法區使用大小	56877
CCSC	壓縮類空間大小	10944
CCSU	壓縮類空間使用大小	6560
YGC	yongGC次數	1389110
YGCT	yongGC消耗時間	24246.291
FGC	fullGC次數	0
FGCT	fullGC消耗時間	0
GCT	GC總消耗時間	24246.291

出問題的瞬態，雖然記憶體比較吃緊，但是還沒有達到OOM的程度，young GC的次數很頻繁，但是full GC卻一次都沒有發生

2.4、執行緒堆疊

問題開始變得比較詭異了，這個時候其實我迫切想知道每個執行緒都在做什麼

2.4.1、jstack [pid]

jstack [pid]當執行這個命令時，卻收到了如下提示：

14: Unable toopen socket file: target process not responding or HotSpot VM not loaded

看起來JVM已經不響應我正常的匯出請求了

2.4.2、jstack -F [pid]

沒辦法只能強制匯出了jstack -F [pid]；共100+個執行緒，簡單擷取幾張堆疊的詳情

可以發現大部分執行緒均被阻塞在了申請記憶體的部分，例如 ByteBuffer.allocate()，這個很明顯就是記憶體吃緊了，還得在記憶體上下功夫

2.5、壓測環境復現？

既然懷疑是記憶體問題，那麼一定可以壓測復現的，於是在我們的壓測環境模擬現場的請求引數，壓測了1周，發現整體執行情況非常平穩，而且垃圾回收相當規律

然後又調整了最大可使用記憶體，再次壓測，問題還是沒有復現

問題雖然沒有復現，不過無非的以下幾種原因：

• bug出現機率很低，壓測環境需要跑很久很久可能都不能觸發
• bug只在特定case下復現，而壓測環境不具備這個case的條件
• 壓測環境與生產環境不是嚴格1比1的，有其他因素影響了bug復現

看來問題比較棘手啊

2.6、Kafka社群

既然到目前為止可走的路基本都堵死了，那隻能去kafka社群翻一下2.8.2這個版本是否存在重大漏洞，雖然我印象中kafka從來沒有出現過如此詭異的場景

關於hang住的場景，社群的case有300+個，這是一件很費精力+耗時的任務，只能硬著頭皮去篩選了。然而大部分是client端因為各種緣由hang住的，臭名昭著的就是consumer的rebalance；關於broker的hang住或者OOM的case也有，不過都是早期(< 0.0.9)的版本導致，沒有發現2.0.0+以上的版本出現過如此嚴重的bug

2.7、Arthas & jmap

Arthas 是一款線上監控診斷產品，透過全域性視角實時檢視應用 load、記憶體、gc、執行緒的狀態資訊，並能在不修改應用程式碼的情況下，對業務問題進行診斷，包括檢視方法呼叫的出入參、異常，監測方法執行耗時，類載入資訊等，大大提升線上問題排查效率。 https://arthas.aliyun.com/doc/

以上，是引自Arthas官網對其概述性的描述，其使用探針技術，可以對執行緒、變數等進行全方位的分析（類似linux的gdb），其提供了豐富的命令：

然而與jstack [pid]命令相似，JVM沒有對Arthas進行任何響應，因此，即便是提供了便捷、強大的功能，在這種場景下也無能為力了，以下是引自Arthas官方對“not responding”的說明：

1. 檢查當前使用者和目標 java 程式是否一致。如果不一致，則切換到同一使用者。JVM 只能 attach 同樣使用者下的 java 程式。
2. 嘗試使用 jstack -l $pid，如果程式沒有反應，則說明程式可能假死，無法響應 JVM attach 訊號。所以同樣基於 attach 機制的 Arthas 無法工作。嘗試使用jmap heapdump 後分析。

接下來嘗試使用jmap將所有記憶體資訊dump下來，與jstack類似，jmap同樣沒有任何響應，只能新增 -F（強制執行）引數：jmap -F -dump:file=/tmp/kafka.dump 14，經過漫長的等待後，最終丟擲了非預期異常

至此，山重水複疑無路，調查似乎陷入了僵局

三、再探

冥冥中感覺事情進展的不對，我們一直像一個無頭蒼蠅似的，每個點都去嘗試調查一番，然而思考的時間太少了，冷靜下來後重新審視一下當前的問題：

1. 首先這個問題是小機率性的發生，而且不具備週期性跟規律性
2. 錯誤日誌、系統日誌、JVM crash日誌、告警日誌，全都沒有，一行都沒有
3. 壓測環境全力發壓10多天，bug不能復現，且壓測的記憶體回收非常穩定
4. 所有執行緒均變為了BLOCKED狀態，而且卡點一般都在申請記憶體處，例如ByteBuffer.allocate()
5. CPU跌0
6. 記憶體相對緊張，達到了76%
7. 出問題前1個小時的GC日誌（頻率、耗時）正常
8. Kafka開源的bug issue中，one by one的檢視，沒有發現類似情況的
9. jstack、jmap、Arthas全部失效，jdk提供的命令必須要加-F才能響應

雖然很像是記憶體溢位的問題，但是我們還是要正視以下3個問題：

• 並沒有OOM的日誌
• GC垃圾回收非常正常
• 記憶體使用率並沒有飈滿

3.1、斷崖式hang機

查閱出問題時間段，該broker各個指標的走勢圖，發現全部都是斷崖式的：

指標	出問題前	出問題後
cpu	cpu不高，且一切正常、平穩	直接跌0
系統load	load維持在8左右，沒有大波動	直接跌0
進出流量	進出流量均在1G/s左右，沒有波動	直接跌0
日誌	一切正常，包括server.log、gc.log等，沒有任何error或者warn	停止任何輸出
訊息處理耗時	ms級別，一切穩定正常	不再響應

正常一個系統出問題，在真正不可用之前會有很多預警指標暴出來，比如：

• GC的回收時間變長
• 處理一次請求的耗時變長
• 系統越來越慢

這些與我面臨的的case是完全不一樣的，上一秒還在敲鑼打鼓，一片繁榮，沒有一絲頹式，下一秒就直接戛然而止，整個世界都安靜了

至此，我們必須快刀斬亂麻，不能再朝著記憶體溢位的方向繼續調研了，這個方向就是一條不歸路。那什麼場景還能導致所有執行緒均為BLOCKED狀態呢？難道是死鎖？ 但kafka broker啟動了100+個執行緒，死鎖即便發生，也只能影響少數幾個執行緒，broker中還有大量的自迴圈執行緒，不可能100+個執行緒全部被阻塞了

不對啊，所有執行緒均被阻塞，只有Stop The World（STW）的時候才會發生，如果正巧這個時候VM thread也被阻塞，那跟我現在要處理的問題豈不是非常吻合。難道JVM或者OS有bug？

3.2、Mix Stack

因為jstack -F [pid]是不會將系統（諸如VM thread）執行緒列印出來的，原因是一般的系統執行緒都是C++棧。因此使用以下命令列印mix stack。所謂混合棧，即Java的棧跟C++放在一起輸出

jstack -m [pid]

這個命令成功返回了VM thread的棧資訊

ox0000ffff99f4da8c __pthread_cond_wait
ox0000ffff997c014c _ZN2os13PlatformEvent4parkEv
ox0000ffff9976f014 _ZN7Monitor5IWaitEP6Thread1
ox0000ffff9976faf0 _ZN7Monitor4waitEblb
ox0000ffff999355dc _ZN20SuspendibleThreadSet11synchronizeEv
ox0000ffff99858a68 _ZN20SafepointSynchronize5beginEv
ox0000ffff999d3124 _ZN8VMThread4loopEv
ox0000ffff999d3458 _ZN8VMThread3runEv
ox0000ffff997b8204 _ZL10java_startP6Thread
ox0000ffff99f47800 start_thread

果然，發現了端倪，VM thread卡在了非常詭異的位置：

SafepointSynchronize::begin()

SuspendibleThreadSet::synchronize()

3.3、新思路

對於JVM的這個問題，Oracle官方給出了排查思路

一共3種型別：

• jstack發現了死鎖
• jstack沒有發現死鎖，且執行緒能給正常dump下來
• jstack無法正常dump

很明顯，我們現在處理的問題是第三種，官方的文件地址如下：

https://docs.oracle.com/en/java/javase/20/troubleshoot/troubleshoot-process-hangs-and-loops.html#GUID-88307E36-5BA7-4EF7-B90D-5B8F028E7890

原文文件提供了非常好的思路，如果你現在也面臨了跟我一樣的問題，強烈建議逐字閱讀原文

此處我簡單總結一下，VM thread，也就是真正執行GC的執行緒，通常只會處於3種狀態：

1. 等待一個VM操作；一般情況下，VM執行緒大部分的時間都處在這個狀態
2. 阻塞所有的執行緒；這個過程也是相對耗時的，需要所有running狀態的執行緒均達到安全點safepoint後才會響應阻塞
3. 執行VM操作；例如執行GC，不再贅述

而現在，VM thread在步驟二阻塞了，也就是有執行緒一直沒有進入安全點，導致VM thread無限期地等下去

3.4、SafePoint & IN_NATIVE

什麼是SafePoint（安全點）呢？

1. 當需要GC時，需要知道哪些物件還被使用，或者已經不被使用可以回收了，這樣就需要每個執行緒的物件使用情況
2. 對於偏向鎖（Biased Lock），在高併發時想要解除偏置，需要執行緒狀態還有獲取鎖的執行緒的精確資訊
3. 對方法進行即時編譯最佳化（OSR棧上替換），或者反最佳化（bailout棧上反最佳化），這需要執行緒究竟執行到方法的哪裡的資訊

對於這些操作，都需要執行緒的各種資訊，例如暫存器中到底有啥，堆使用資訊以及棧方法程式碼資訊等等等等，並且做這些操作的時候，執行緒需要暫停，等到這些操作完成，否則會有併發問題。這就需要 SafePoint

對於安全點的介紹以及其是如何實現的，可以參照這篇文章 https://cloud.tencent.com/developer/article/1811372

簡單來說，就是如果不為執行緒設定安全點，而是讓執行緒在任意位置BLOCKED，可能會帶來很多併發問題

什麼地方會設定安全點呢？包括但不限於：

1. 迴圈體的結尾
2. 方法返回前
3. 呼叫方法的call之後
4. 丟擲異常的位置

甚至JIT也可能對安全點在效能上有一定的最佳化

為什麼VM thread會卡在“等待所有業務執行緒進入SafePoint”這個階段呢？所有的執行緒不是均已經進入BLOCKED狀態了麼？ 然後我又重新檢查了一遍所有執行緒，還真有一個不是BLOCKED狀態的， jstack -m [pid] 的結果

ox0000ffff99de7dd8 __GI___poll
ox0000fffed7871a3c NET_Timeout0
ox0000fffe786ec40 Java_java_net_PlainSocketImpl_socketAccept
ox0000ffff8c015628 * java.net.PlainSocketImpl.socketAccept(java.net.SocketImpl) bci:0 (Interpreted frame)
ox0000ffff8c008498 * java.net.AbstractPlainSocketImpl.accept(java.net.SocketImpl) bci:7 line:409 (Interpreted frame)
ox0000ffff8c008498 * java.net.ServerSocket.implAccept(java.net.SocketImpl)
ox0000ffff8c008498 * java.net.ServerSocket.accept()
ox0000ffff8c008380 * sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept()
ox0000ffff8c008380 * sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop()

而透過jstack -F [pid]列印出來的執行緒堆疊如下

直觀感覺就是這個執行緒的IN_NATIVE狀態，阻止了VM thread順利進入SafePoint了

3.5、Aarch64 Linux bug？

難道是linux呼叫poll函式的未知bug ？無獨有偶，還真有遇到過類似bug的同學

原文地址： https://github.com/rust-lang/cargo/issues/10007

堆疊資訊、bug詳情都異常吻合，也是執行緒hang死不動，甚至這裡把linux的bug都已經貼了出來

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=46c4c9d1beb7f5b4cec4dd90e7728720583ee348

公司內有專門做作業系統的同學，趕緊向其求證這個bug是否存在；因為上下文比較多，把背景介紹完，OS的小夥伴經過嚴密驗證後，得出結論，這個bug在我們的雲上環境已經被修復了

難道IN_NATIVE狀態的執行緒不影響GC執行緒同步進入安全點？

3.6、再談 IN_NATIVE

IN_NATIVE，如其名，就是執行緒進入了native方法中，如果一個執行緒進入了native方法，它的執行緒狀態可能會根據匯出的命令不同而不同：

• RUNNING jstack [pid]
• IN_NATIVE jstack -F [pid]、jstack -m [pid]

為什麼一個 IN_NATIVE 狀態的執行緒不會阻止GC執行緒順利達到SafePoint呢？我在JDK原始碼及註釋中找到了答案

雖然處於IN_NATIVE狀態的執行緒不會阻塞，但是其在native呼叫返回後，首先就會檢查safepoint：

Running in native code When returning from the native code, a Java thread must check the safepoint _state to see if we must block. If the VM thread sees a Java thread in native, it does not wait for this thread to block.

此處也好理解，執行緒在呼叫native方法時，是不會對JVM產生影響的，尤其是不會為heap記憶體新增垃圾，而其在native結束後會馬上檢查安全點，如果此時GC還未結束，當前執行緒也會被馬上掛起

為了驗證這個猜想，我自己構建了一個C++庫，裡面新建了一個native方法，然後在方法內執行無限迴圈while(1==1){}，然後額外新建多個執行緒去開闢空間，讓其快速觸發GC，最終驗證下來，GC一起正常

看來問題跟IN_NATIVE狀態沒有關係

3.7、JVM bug

既然已經排除 IN_NATIVE 狀態的執行緒bug，那就還是需要回歸到GC本身的原始碼上來。為什麼VM thread hang在了一個本不應該被hang住的位置？

通常遇到JVM hang死的情況，可能是有的業務執行緒一直遲遲不能達到安全點，導致將其他業務執行緒均blocked後，VM thread執行緒自己也被阻塞了。而我們現在這個問題卻是其需要將所有的marking threads都停掉，而marking threads本身又都是JVM來管理的

至此，感覺十有八九是JDK的自身的bug了。向JDK社群報告當前的這個case，原文地址：https://github.com/adoptium/adoptium-support/issues/912

很幸運，得到了大佬 Martijn Verburg 的回覆

Martijn Verburg明確說了，在版本1.8.0_131~1.8.0_382，是存在JDK hang死的bug的，我們現在的JDK版本是1.8.0_312，正好介於有問題的版本之間。因此我們可能不幸中標了，遇到了：

 

JDK BUG

 

下一步準備升級一下小版本，然後在壓測環境進行迴歸測試，然後正式釋出到生產環境

PS：最近沒少翻看GC部分的C++程式碼，裡面各種併發控制，真心不好讀啊，向那些不斷完善openjdk的前輩們致敬

 

參考文獻

• https://hotspot-dev.openjdk.java.narkive.com/03ycGzRS/jvm-hanging-when-using-g1gc-on-jdk8-b78-or-b79-linux-32-bit

• 一個與本文及其相似的bug，最終也是認定為jdk bug

• https://docs.oracle.com/en/java/javase/20/troubleshoot/troubleshoot-process-hangs-and-loops.html#GUID-88307E36-5BA7-4EF7-B90D-5B8F028E7890

• Oracle官網文件，提供hang死排查思路

• https://issues.apache.org/jira/browse/KAFKA-14063?jql=project%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22

• 解析message導致的OOM

• https://issues.apache.org/jira/browse/KAFKA-7863?jql=project%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22

• JMX 導致的OOM問題，我們專案也用到了JMX，不過case不一樣

• https://issues.apache.org/jira/browse/KAFKA-6777?jql=project%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22

• 經典JVM bug，GC為了儘可能完成任務，導致JVM假死的case

• https://issues.apache.org/jira/browse/KAFKA-14342?jql=project%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22

• KafkaOffsetBackingStore引發的bug，曾經一度懷疑是kafka的mm2引發的，因為我們生產環境用到了mm2

• https://stackoverflow.com/questions/26140182/running-jmap-getting-unable-to-open-socket-file

• 解釋jstack、jmap命令執行時，是否增加-F引數，對應的執行過程不同

• https://hllvm-group.iteye.com/group/topic/41015

• JVM hang住，所有執行緒BLOCKED（包括GC執行緒），Eden區100% （與我們case及其相近，不過是修改GC原始碼引發的bug）

• https://stackoverflow.com/questions/36616126/jvm-hangs-after-migrating-to-jdk1-8-0-74

• JVM hangs after migrating to jdk1.8.0_74；也是hang死的case，不過沒有定論

• https://stackoverflow.com/questions/54278053/why-java-safepoint-never-reached-thread-hang-safepoint-timeout

• Why Java safepoint never reached? Thread hang, safepoint timeout

• https://blog.csdn.net/qq_43799161/article/details/130967749

• JVM原始碼分析VMThread執行緒

• https://access.redhat.com/solutions/6240311

• 紅帽官網，也是遇到hang死情況，不過他們的卡點是SafepointSynchronize::begin

• https://www.jianshu.com/p/43bc97230299

• 記一次線上JVM長時間STW之分析

• http://jcdav.is/2015/11/09/More-JVM-Signal-Tricks/

• 一個小測試，主動讓JVM Stop The World

• https://blog.csdn.net/iter_zc/article/details/41892567

• SafePoint與執行緒阻塞

• https://www.infoq.cn/article/jvm-bug-thread

• 一些關於GC的C++程式碼導讀

• https://github.com/rust-lang/cargo/issues/10007

• linux關於__GI___poll的bug發現