从一次Kafka宕机说起(JVM hang)

一、背景

时间大概是在夏天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”的说明:

  1. 检查当前用户和目标 java 进程是否一致。如果不一致,则切换到同一用户。JVM 只能 attach 同样用户下的 java 进程。
  2. 尝试使用 jstack -l $pid,如果进程没有反应,则说明进程可能假死,无法响应 JVM attach 信号。所以同样基于 attach 机制的 Arthas 无法工作。尝试使用jmap heapdump 后分析。

接下来尝试使用jmap将所有内存信息dump下来,与jstack类似,jmap同样没有任何响应,只能添加 -F(强制执行)参数:jmap -F -dump:file=/tmp/kafka.dump 14,经过漫长的等待后,最终抛出了非预期异常

至此,山重水复疑无路,调查似乎陷入了僵局

三、再探

冥冥中感觉事情进展的不对,我们一直像一个无头苍蝇似的,每个点都去尝试调查一番,然而思考的时间太少了,冷静下来后重新审视一下当前的问题:

  1. 首先这个问题是小概率性的发生,而且不具备周期性跟规律性
  2. 错误日志、系统日志、JVM crash日志、告警日志,全都没有,一行都没有
  3. 压测环境全力发压10多天,bug不能复现,且压测的内存回收非常稳定
  4. 所有线程均变为了BLOCKED状态,而且卡点一般都在申请内存处,例如ByteBuffer.allocate()
  5. CPU跌0
  6. 内存相对紧张,达到了76%
  7. 出问题前1个小时的GC日志(频率、耗时)正常
  8. Kafka开源的bug issue中,one by one的查看,没有发现类似情况的
  9. 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种状态:

  1. 等待一个VM操作;一般情况下,VM线程大部分的时间都处在这个状态
  2. 阻塞所有的线程;这个过程也是相对耗时的,需要所有running状态的线程均达到安全点safepoint后才会响应阻塞
  3. 执行VM操作;例如执行GC,不再赘述

而现在,VM thread在步骤二阻塞了,也就是有线程一直没有进入安全点,导致VM thread无限期地等下去

3.4、SafePoint & IN_NATIVE

什么是SafePoint(安全点)呢?

  1. 当需要GC时,需要知道哪些对象还被使用,或者已经不被使用可以回收了,这样就需要每个线程的对象使用情况
  2. 对于偏向锁(Biased Lock),在高并发时想要解除偏置,需要线程状态还有获取锁的线程的精确信息
  3. 对方法进行即时编译优化(OSR栈上替换),或者反优化(bailout栈上反优化),这需要线程究竟运行到方法的哪里的信息

对于这些操作,都需要线程的各种信息,例如寄存器中到底有啥,堆使用信息以及栈方法代码信息等等等等,并且做这些操作的时候,线程需要暂停,等到这些操作完成,否则会有并发问题。这就需要 SafePoint

对于安全点的介绍以及其是如何实现的,可以参照这篇文章 https://cloud.tencent.com/developer/article/1811372

简单来说,就是如果不为线程设置安全点,而是让线程在任意位置BLOCKED,可能会带来很多并发问题

什么地方会设置安全点呢?包括但不限于:

  1. 循环体的结尾
  2. 方法返回前
  3. 调用方法的call之后
  4. 抛出异常的位置

甚至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 的回复

我们现在的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发现

热门相关:宠物小精灵之庭树   紫府仙缘   重生之女将星   异能特工:军火皇后   宠物小精灵之庭树