一、背景

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

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

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

下麵是一些環境信息

二、初探

與上次不同，這次通過多方協商，將現場出問題的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[]，這個好理解，因為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的歷史情況

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

出問題的瞬態，雖然記憶體比較吃緊，但是還沒有達到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各個指標的走勢圖，發現全部都是斷崖式的：

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

• 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發現