从一次Kafka宕机说起（JVM hang）

2023-10-18 11:02 由昔久发表于 #后端开发

一、背景

时间大概是在夏天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#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一起正常