一、背景
时间大概是在夏天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
很明显,我们现在处理的问题是第三种,官方的文档地址如下:
原文文档提供了非常好的思路,如果你现在也面临了跟我一样的问题,强烈建议逐字阅读原文
此处我简单总结一下,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的同学
![](/i/l/?n=23&i=blog/2109301/202310/2109301-20231018105854381-1700480653.png)
原文地址: https://github.com/rust-lang/cargo/issues/10007
堆栈信息、bug详情都异常吻合,也是线程hang死不动,甚至这里把linux的bug都已经贴了出来
公司内有专门做操作系统的同学,赶紧向其求证这个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 的回复
我们现在的JDK版本是1.8.0_312,正好介于有问题的版本间。下一步准备升级一下小版本,然后在压测环境进行回归测试,然后正式发布到生产环境
PS:最近没少翻看GC部分的C++代码,里面各种并发控制,真心不好读啊,向那些不断完善openjdk的前辈们致敬
四、后续
如有新的进展,将在这里完善
参考文献
- 一个与本文及其相似的bug,最终也是认定为jdk bug
- Oracle官网文档,提供hang死排查思路
- 解析message导致的OOM
- JMX 导致的OOM问题,我们项目也用到了JMX,不过case不一样
- 经典JVM bug,GC为了尽可能完成任务,导致JVM假死的case
- KafkaOffsetBackingStore引发的bug,曾经一度怀疑是kafka的mm2引发的,因为我们生产环境用到了mm2
- 解释jstack、jmap命令执行时,是否增加
-F
参数,对应的执行过程不同
- JVM hang住,所有线程BLOCKED(包括GC线程),Eden区100% (与我们case及其相近,不过是修改GC源码引发的bug)
- JVM hangs after migrating to jdk1.8.0_74;也是hang死的case,不过没有定论
- Why Java safepoint never reached? Thread hang, safepoint timeout
- JVM源码分析VMThread线程
- 红帽官网,也是遇到hang死情况,不过他们的卡点是SafepointSynchronize::begin
- 记一次线上JVM长时间STW之分析
- 一个小测试,主动让JVM Stop The World
- SafePoint与线程阻塞
- 一些关于GC的C++代码导读
- linux关于
__GI___poll
的bug发现