一、背景

時(shí)間大概是在夏天7月份，突然收到小伙伴的情報(bào)，我們線上的一個(gè)kafka實(shí)例的某個(gè)broker突然不提供服務(wù)了，也沒看到什么異常日志，反正就是生產(chǎn)、消費(fèi)都停了。因?yàn)槭蔷€上服務(wù)，而且進(jìn)程還在，就是不提供服務(wù)了，第一反應(yīng)就是保留一下 stack 信息，先重啟吧

因?yàn)檫@個(gè)現(xiàn)象是第一次出現(xiàn)，不確定是哪里的bug，操作系統(tǒng)、機(jī)器等都有可能。當(dāng)時(shí)也沒重視這個(gè)問題，判斷可能是個(gè)偶發(fā)現(xiàn)象，broker重啟恢復(fù)后，因?yàn)闃I(yè)務(wù)繁忙，就把這事兒給擱置了

然而僅僅2個(gè)月后，這個(gè)問題又復(fù)現(xiàn)了，而且與上次出問題的機(jī)器不是同一臺，我知道這次沒法視而不見，可能要打一場硬仗了

 

二、初探

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

2.1、日志清除策略bug？

最先想到的就是內(nèi)存泄露，讓現(xiàn)場的同學(xué)幫忙執(zhí)行命令：jmap -histo [pid]，主要想看下每個(gè)類占用空間的情況

 

首先感覺有問題的就是kafka.log.LogSegment的數(shù)量，達(dá)到了10萬+的數(shù)量，我們知道在kafka中，每個(gè)LogSegment實(shí)例就代表了一個(gè)日志切片，然后現(xiàn)場的日志保留時(shí)長是3天，怎么可能會有這么多文件切片呢？

突然想到我們之前針對Kafka的文件過期增加了一個(gè)新的feature：“即kafka文件的總大小不能超過指定的閾值，如果超過的話，會將最老的文件刪除”，難道這個(gè)feature存在未知bug，導(dǎo)致某些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新增這個(gè)特性中，只是在日志清理線程的最后，判斷日志空間是否超限，對原有的邏輯沒有侵入，而且也完全復(fù)用了kafka原生的清理邏輯，即將要?jiǎng)h除的.log、.timeinde、.index等文件后綴添加.deleted。反復(fù)review了這個(gè)特性的代碼，整體邏輯應(yīng)該是沒問題的

不對啊，那客戶當(dāng)前broker的LogSegment怎么會這么大？后來發(fā)現(xiàn)客戶在broker部署使用了多文件目錄結(jié)構(gòu)，反復(fù)確認(rèn)了topic數(shù)量、partition數(shù)量后，證實(shí)用戶的LogSegment確實(shí)很多，雖然有性能上的一些問題，但并不是本地hang死的根源，因此需要切換思路

 

2.2、內(nèi)存占用分析

重新回到各個(gè)對象占用空間上來，我將前幾名占用空間比較大的類做了整理：

其實(shí)最大的還是byte[]，這個(gè)好理解，因?yàn)閗afka后端存儲數(shù)據(jù)的時(shí)候，都是面向字節(jié)存儲的，因此不論是網(wǎng)絡(luò)線程還是IO線程，都會頻繁的在堆內(nèi)存開辟空間 ByteBuffer.allocate()，然后很快可以在垃圾回收的時(shí)候被回收走，整體占用情況還是比較正常的

 

好像這里相對比較正常，沒有發(fā)現(xiàn)可疑之處。垃圾回收的日志正常嗎？

2.3、垃圾回收日志分析

目標(biāo)機(jī)器的堆內(nèi)存分配的很大，有足足24G的空間，之前遇到過大內(nèi)存實(shí)例導(dǎo)致GC停頓很嚴(yán)重的case，會不會跟垃圾回收有關(guān)呢？但為了避免這種情況，已經(jīng)為當(dāng)前客戶實(shí)例啟用了G1，部分啟動命令如下

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

 

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

又檢查了一下其他健康實(shí)例的GC情況，發(fā)現(xiàn)也類似，雖然這個(gè)配置項(xiàng)設(shè)置的有待商榷，但應(yīng)該不是導(dǎo)致hang的根因

 

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

 

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

出問題的瞬態(tài)，雖然內(nèi)存比較吃緊，但是還沒有達(dá)到OOM的程度，young GC的次數(shù)很頻繁，但是full GC卻一次都沒有發(fā)生

2.4、線程堆棧

問題開始變得比較詭異了，這個(gè)時(shí)候其實(shí)我迫切想知道每個(gè)線程都在做什么

2.4.1、jstack [pid]

jstack [pid]當(dāng)執(zhí)行這個(gè)命令時(shí)，卻收到了如下提示：

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

看起來JVM已經(jīng)不響應(yīng)我正常的導(dǎo)出請求了

2.4.2、jstack -F [pid]

沒辦法只能強(qiáng)制導(dǎo)出了jstack -F [pid]；共100+個(gè)線程，簡單截取幾張堆棧的詳情

可以發(fā)現(xiàn)大部分線程均被阻塞在了申請內(nèi)存的部分，例如 ByteBuffer.allocate()，這個(gè)很明顯就是內(nèi)存吃緊了，還得在內(nèi)存上下功夫

2.5、壓測環(huán)境復(fù)現(xiàn)？

既然懷疑是內(nèi)存問題，那么一定可以壓測復(fù)現(xiàn)的，于是在我們的壓測環(huán)境模擬現(xiàn)場的請求參數(shù)，壓測了1周，發(fā)現(xiàn)整體運(yùn)行情況非常平穩(wěn)，而且垃圾回收相當(dāng)規(guī)律

然后又調(diào)整了最大可使用內(nèi)存，再次壓測，問題還是沒有復(fù)現(xiàn)

問題雖然沒有復(fù)現(xiàn)，不過無非的以下幾種原因：

• bug出現(xiàn)幾率很低，壓測環(huán)境需要跑很久很久可能都不能觸發(fā)
• bug只在特定case下復(fù)現(xiàn)，而壓測環(huán)境不具備這個(gè)case的條件
• 壓測環(huán)境與生產(chǎn)環(huán)境不是嚴(yán)格1比1的，有其他因素影響了bug復(fù)現(xiàn)

看來問題比較棘手啊

2.6、Kafka社區(qū)

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

 

關(guān)于hang住的場景，社區(qū)的case有300+個(gè)，這是一件很費(fèi)精力+耗時(shí)的任務(wù)，只能硬著頭皮去篩選了。然而大部分是client端因?yàn)楦鞣N緣由hang住的，臭名昭著的就是consumer的rebalance；關(guān)于broker的hang住或者OOM的case也有，不過都是早期(< 0.0.9)的版本導(dǎo)致，沒有發(fā)現(xiàn)2.0.0+以上的版本出現(xiàn)過如此嚴(yán)重的bug

 

2.7、Arthas & jmap

 

以上，是引自Arthas官網(wǎng)對其概述性的描述，其使用探針技術(shù)，可以對線程、變量等進(jìn)行全方位的分析（類似linux的gdb），其提供了豐富的命令：

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

 

接下來嘗試使用jmap將所有內(nèi)存信息dump下來，與jstack類似，jmap同樣沒有任何響應(yīng)，只能添加 -F（強(qiáng)制執(zhí)行）參數(shù)：jmap -F -dump:file=/tmp/kafka.dump 14，經(jīng)過漫長的等待后，最終拋出了非預(yù)期異常

 

至此，山重水復(fù)疑無路，調(diào)查似乎陷入了僵局

三、再探

冥冥中感覺事情進(jìn)展的不對，我們一直像一個(gè)無頭蒼蠅似的，每個(gè)點(diǎn)都去嘗試調(diào)查一番，然而思考的時(shí)間太少了，冷靜下來后重新審視一下當(dāng)前的問題：

1. 首先這個(gè)問題是小概率性的發(fā)生，而且不具備周期性跟規(guī)律性
2. 錯(cuò)誤日志、系統(tǒng)日志、JVM crash日志、告警日志，全都沒有，一行都沒有
3. 壓測環(huán)境全力發(fā)壓10多天，bug不能復(fù)現(xiàn)，且壓測的內(nèi)存回收非常穩(wěn)定
4. 所有線程均變?yōu)榱?code class="ne-code">BLOCKED狀態(tài)，而且卡點(diǎn)一般都在申請內(nèi)存處，例如ByteBuffer.allocate()
5. CPU跌0
6. 內(nèi)存相對緊張，達(dá)到了76%
7. 出問題前1個(gè)小時(shí)的GC日志（頻率、耗時(shí)）正常
8. Kafka開源的bug issue中，one by one的查看，沒有發(fā)現(xiàn)類似情況的
9. jstack、jmap、Arthas全部失效，jdk提供的命令必須要加-F才能響應(yīng)

 

雖然很像是內(nèi)存溢出的問題，但是我們還是要正視以下3個(gè)問題：

• 并沒有OOM的日志
• GC垃圾回收非常正常
• 內(nèi)存使用率并沒有飚滿

3.1、斷崖式hang機(jī)

查閱出問題時(shí)間段，該broker各個(gè)指標(biāo)的走勢圖，發(fā)現(xiàn)全部都是斷崖式的：

正常一個(gè)系統(tǒng)出問題，在真正不可用之前會有很多預(yù)警指標(biāo)暴出來，比如：

• GC的回收時(shí)間變長
• 處理一次請求的耗時(shí)變長
• 系統(tǒng)越來越慢

 

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

至此，我們必須快刀斬亂麻，不能再朝著內(nèi)存溢出的方向繼續(xù)調(diào)研了，這個(gè)方向就是一條不歸路。那什么場景還能導(dǎo)致所有線程均為BLOCKED狀態(tài)呢？難道是死鎖？ 但kafka broker啟動了100+個(gè)線程，死鎖即便發(fā)生，也只能影響少數(shù)幾個(gè)線程，broker中還有大量的自循環(huán)線程，不可能100+個(gè)線程全部被阻塞了

 

不對啊，所有線程均被阻塞，只有Stop The World（STW）的時(shí)候才會發(fā)生，如果正巧這個(gè)時(shí)候VM thread也被阻塞，那跟我現(xiàn)在要處理的問題豈不是非常吻合。難道JVM或者OS有bug？

3.2、Mix Stack

因?yàn)?code class="ne-code">jstack -F [pid]是不會將系統(tǒng)（諸如VM thread）線程打印出來的，原因是一般的系統(tǒng)線程都是C++棧。因此使用以下命令打印mix stack。所謂混合棧，即Java的棧跟C++放在一起輸出

jstack -m [pid]

 

這個(gè)命令成功返回了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

果然，發(fā)現(xiàn)了端倪，VM thread卡在了非常詭異的位置：

SafepointSynchronize::begin()

SuspendibleThreadSet::synchronize()

3.3、新思路

對于JVM的這個(gè)問題，Oracle官方給出了排查思路

一共3種類型：

• jstack發(fā)現(xiàn)了死鎖
• jstack沒有發(fā)現(xiàn)死鎖，且線程能給正常dump下來
• jstack無法正常dump

 

很明顯，我們現(xiàn)在處理的問題是第三種，官方的文檔地址如下：

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

 

原文文檔提供了非常好的思路，如果你現(xiàn)在也面臨了跟我一樣的問題，強(qiáng)烈建議逐字閱讀原文

此處我簡單總結(jié)一下，VM thread，也就是真正執(zhí)行GC的線程，通常只會處于3種狀態(tài)：

1. 等待一個(gè)VM操作；一般情況下，VM線程大部分的時(shí)間都處在這個(gè)狀態(tài)
2. 阻塞所有的線程；這個(gè)過程也是相對耗時(shí)的，需要所有running狀態(tài)的線程均達(dá)到安全點(diǎn)safepoint后才會響應(yīng)阻塞
3. 執(zhí)行VM操作；例如執(zhí)行GC，不再贅述

 

而現(xiàn)在，VM thread在步驟二阻塞了，也就是有線程一直沒有進(jìn)入安全點(diǎn)，導(dǎo)致VM thread無限期地等下去

3.4、SafePoint & IN_NATIVE

什么是SafePoint（安全點(diǎn)）呢？

對于安全點(diǎn)的介紹以及其是如何實(shí)現(xiàn)的，可以參照這篇文章 https://cloud.tencent.com/developer/article/1811372

簡單來說，就是如果不為線程設(shè)置安全點(diǎn)，而是讓線程在任意位置BLOCKED，可能會帶來很多并發(fā)問題

 

什么地方會設(shè)置安全點(diǎn)呢？包括但不限于：

1. 循環(huán)體的結(jié)尾
2. 方法返回前
3. 調(diào)用方法的call之后
4. 拋出異常的位置

甚至JIT也可能對安全點(diǎn)在性能上有一定的優(yōu)化

 

為什么VM thread會卡在“等待所有業(yè)務(wù)線程進(jìn)入SafePoint”這個(gè)階段呢？所有的線程不是均已經(jīng)進(jìn)入BLOCKED狀態(tài)了么？ 然后我又重新檢查了一遍所有線程，還真有一個(gè)不是BLOCKED狀態(tài)的， jstack -m [pid] 的結(jié)果

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]打印出來的線程堆棧如下

 

直觀感覺就是這個(gè)線程的IN_NATIVE狀態(tài)，阻止了VM thread順利進(jìn)入SafePoint了

3.5、Aarch64 Linux bug？

難道是linux調(diào)用poll函數(shù)的未知bug ？無獨(dú)有偶，還真有遇到過類似bug的同學(xué)

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

堆棧信息、bug詳情都異常吻合，也是線程hang死不動，甚至這里把linux的bug都已經(jīng)貼了出來

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

 

公司內(nèi)有專門做操作系統(tǒng)的同學(xué)，趕緊向其求證這個(gè)bug是否存在；因?yàn)樯舷挛谋容^多，把背景介紹完，OS的小伙伴經(jīng)過嚴(yán)密驗(yàn)證后，得出結(jié)論，這個(gè)bug在我們的云上環(huán)境已經(jīng)被修復(fù)了

難道IN_NATIVE狀態(tài)的線程不影響GC線程同步進(jìn)入安全點(diǎn)？

 

3.6、再談 IN_NATIVE

IN_NATIVE，如其名，就是線程進(jìn)入了native方法中，如果一個(gè)線程進(jìn)入了native方法，它的線程狀態(tài)可能會根據(jù)導(dǎo)出的命令不同而不同：

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

為什么一個(gè) IN_NATIVE 狀態(tài)的線程不會阻止GC線程順利達(dá)到SafePoint呢？我在JDK源碼及注釋中找到了答案

雖然處于IN_NATIVE狀態(tài)的線程不會阻塞，但是其在native調(diào)用返回后，首先就會檢查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.

此處也好理解，線程在調(diào)用native方法時(shí)，是不會對JVM產(chǎn)生影響的，尤其是不會為heap內(nèi)存新增垃圾，而其在native結(jié)束后會馬上檢查安全點(diǎn)，如果此時(shí)GC還未結(jié)束，當(dāng)前線程也會被馬上掛起

 

為了驗(yàn)證這個(gè)猜想，我自己構(gòu)建了一個(gè)C++庫，里面新建了一個(gè)native方法，然后在方法內(nèi)執(zhí)行無限循環(huán)while(1==1){}，然后額外新建多個(gè)線程去開辟空間，讓其快速觸發(fā)GC，最終驗(yàn)證下來，GC一起正常

 

看來問題跟IN_NATIVE狀態(tài)沒有關(guān)系

3.7、JVM bug

既然已經(jīng)排除 IN_NATIVE 狀態(tài)的線程bug，那就還是需要回歸到GC本身的源碼上來。為什么VM thread hang在了一個(gè)本不應(yīng)該被hang住的位置？

 

通常遇到JVM hang死的情況，可能是有的業(yè)務(wù)線程一直遲遲不能達(dá)到安全點(diǎn)，導(dǎo)致將其他業(yè)務(wù)線程均blocked后，VM thread線程自己也被阻塞了。而我們現(xiàn)在這個(gè)問題卻是其需要將所有的marking threads都停掉，而marking threads本身又都是JVM來管理的

至此，感覺十有八九是JDK的自身的bug了。向JDK社區(qū)報(bào)告當(dāng)前的這個(gè)case，原文地址：https://github.com/adoptium/adoptium-support/issues/912

 

很幸運(yùn)，得到了大佬 Martijn Verburg 的回復(fù)

下一步準(zhǔn)備升級一下小版本，然后在壓測環(huán)境進(jìn)行回歸測試，然后正式發(fā)布到生產(chǎn)環(huán)境

 

PS：最近沒少翻看GC部分的C++代碼，里面各種并發(fā)控制，真心不好讀啊，向那些不斷完善openjdk的前輩們致敬

 

 

參考文獻(xiàn)

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

• 一個(gè)與本文及其相似的bug，最終也是認(rèn)定為jdk bug

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

• Oracle官網(wǎng)文檔，提供hang死排查思路

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

• 解析message導(dǎo)致的OOM

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

• JMX 導(dǎo)致的OOM問題，我們項(xiàng)目也用到了JMX，不過case不一樣

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

• 經(jīng)典JVM bug，GC為了盡可能完成任務(wù)，導(dǎo)致JVM假死的case

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

• KafkaOffsetBackingStore引發(fā)的bug，曾經(jīng)一度懷疑是kafka的mm2引發(fā)的，因?yàn)槲覀兩a(chǎn)環(huán)境用到了mm2

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

• 解釋jstack、jmap命令執(zhí)行時(shí)，是否增加-F參數(shù)，對應(yīng)的執(zhí)行過程不同

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

• JVM hang住，所有線程BLOCKED（包括GC線程），Eden區(qū)100% （與我們case及其相近，不過是修改GC源碼引發(fā)的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

• 紅帽官網(wǎng)，也是遇到hang死情況，不過他們的卡點(diǎn)是SafepointSynchronize::begin

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

• 記一次線上JVM長時(shí)間STW之分析

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

• 一個(gè)小測試，主動讓JVM Stop The World

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

• SafePoint與線程阻塞

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

• 一些關(guān)于GC的C++代碼導(dǎo)讀

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

• linux關(guān)于__GI___poll的bug發(fā)現(xiàn)