一、背景

時間大概是在夏天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」的說明：

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

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

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

三、再探

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

首先這個問題是小概率性的發生，而且不具備週期性跟規律性
錯誤紀錄檔、系統紀錄檔、JVM crash紀錄檔、告警紀錄檔，全都沒有，一行都沒有
壓測環境全力發壓10多天，bug不能復現，且壓測的記憶體回收非常穩定
所有執行緒均變為了BLOCKED狀態，而且卡點一般都在申請記憶體處，例如ByteBuffer.allocate()
CPU跌0
記憶體相對緊張，達到了76%
出問題前1個小時的GC紀錄檔（頻率、耗時）正常
Kafka開源的bug issue中，one by one的檢視，沒有發現類似情況的
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

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

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

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

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

3.4、SafePoint & IN_NATIVE

什麼是SafePoint（安全點）呢？

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

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

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

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

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

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

甚至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一起正常