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”的说明：
检查当前用户和目标 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各个指标的走势图，发现全部都是断崖式的：
这些与我面临的的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种状态：
等待一个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一起正常
看来问题跟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的前辈们致敬
四、后记--2024年04月
在文章首次发布的同时，我们也将生产环境的版本升级至了JDK11，现在时间是2024年4月份，距离我们升级JDK版本已经过去了大半年的时间
在升级之前，随着我们线上机器的增多，该问题几乎每周都要出现
升级之后，此问题再没有出现过
至此，可敲定JDK Bug的结论，此问题闭环
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发现
