一、背景时间大概是在夏天7月份突然收到小伙伴的情报我们线上的一个kafka实例的某个broker突然不提供服务了也没看到什么异常日志反正就是生产、消费都停了。因为是线上服务而且进程还在就是不提供服务了第一反应就是保留一下 stack 信息先重启吧因为这个现象是第一次出现不确定是哪里的bug操作系统、机器等都有可能。当时也没重视这个问题判断可能是个偶发现象broker重启恢复后因为业务繁忙就把这事儿给搁置了然而仅仅2个月后这个问题又复现了而且与上次出问题的机器不是同一台我知道这次没法视而不见可能要打一场硬仗了下面是一些环境信息工程版本Kafka2.8.2JDK versionOpenJDK 1.8.0_312-b07OSlinux架构aarch64k8sv1.18.8golanggo1.13.15Heap Size24GJava GCG1二、初探与上次不同这次通过多方协商将现场出问题的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(sLog cleanup completed. $total files deleted in (time.milliseconds - startMs) / 1000 seconds\n) debug(sLog 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[]10993221391393267213269M12.9GDouble494873821187697168/1024/10241132M1.1GConcurrentSkipList24375854585020496/1024/1024557Mchar[]296323392296323392/1024/1024282M其实最大的还是byte[]这个好理解因为kafka后端存储数据的时候都是面向字节存储的因此不论是网络线程还是IO线程都会频繁的在堆内存开辟空间ByteBuffer.allocate()然后很快可以在垃圾回收的时候被回收走整体占用情况还是比较正常的好像这里相对比较正常没有发现可疑之处。垃圾回收的日志正常吗2.3、垃圾回收日志分析目标机器的堆内存分配的很大有足足24G的空间之前遇到过大内存实例导致GC停顿很严重的case会不会跟垃圾回收有关呢但为了避免这种情况已经为当前客户实例启用了G1部分启动命令如下java -Xmx24576m -Xms24576m -server -XX:UseG1GC -XX:MaxGCPauseMillis20 -XX:InitiatingHeapOccupancyPercent35 -XX:ExplicitGCInvokesConcurrent -XX:MaxInlineLevel15难道是配置GC停顿时长MaxGCPauseMillis20过小的缘故 G1中相对比较重要的一个参数了用来控制Stop The World (STW) 的最大时长。检查了一下历史记录发现确实比较频繁基本上2~3秒就会触发一次又检查了一下其他健康实例的GC情况发现也类似虽然这个配置项设置的有待商榷但应该不是导致hang的根因接着通过jstat -gc [pid]命令分析了下GC的历史情况原输出没有对齐整理后如下EC伊甸区总大小15794176 15GEU伊甸区使用大小15040512 14.3GOC老年代大小9338880 8.9GOU老年代使用大小6832518 6.5GMC方法区大小79552 77MMU方法区使用大小56877CCSC压缩类空间大小10944CCSU压缩类空间使用大小6560YGCyongGC次数1389110YGCTyongGC消耗时间24246.291FGCfullGC次数0FGCTfullGC消耗时间0GCTGC总消耗时间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以上的版本出现过如此严重的bug2.7、Arthas jmapArthas 是一款线上监控诊断产品通过全局视角实时查看应用 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各个指标的走势图发现全部都是断崖式的指标出问题前出问题后cpucpu不高且一切正常、平稳直接跌0系统loadload维持在8左右没有大波动直接跌0进出流量进出流量均在1G/s左右没有波动直接跌0日志一切正常包括server.log、gc.log等没有任何error或者warn停止任何输出消息处理耗时ms级别一切稳定正常不再响应正常一个系统出问题在真正不可用之前会有很多预警指标暴出来比如GC的回收时间变长处理一次请求的耗时变长系统越来越慢这些与我面临的的case是完全不一样的上一秒还在敲锣打鼓一片繁荣没有一丝颓式下一秒就直接戛然而止整个世界都安静了至此我们必须快刀斩乱麻不能再朝着内存溢出的方向继续调研了这个方向就是一条不归路。那什么场景还能导致所有线程均为BLOCKED状态呢难道是死锁 但kafka broker启动了100个线程死锁即便发生也只能影响少数几个线程broker中还有大量的自循环线程不可能100个线程全部被阻塞了不对啊所有线程均被阻塞只有Stop The WorldSTW的时候才会发生如果正巧这个时候VM thread也被阻塞那跟我现在要处理的问题岂不是非常吻合。难道JVM或者OS有bug3.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/?id46c4c9d1beb7f5b4cec4dd90e7728720583ee348公司内有专门做操作系统的同学赶紧向其求证这个bug是否存在因为上下文比较多把背景介绍完OS的小伙伴经过严密验证后得出结论这个bug在我们的云上环境已经被修复了难道IN_NATIVE状态的线程不影响GC线程同步进入安全点3.6、再谈 IN_NATIVEIN_NATIVE如其名就是线程进入了native方法中如果一个线程进入了native方法它的线程状态可能会根据导出的命令不同而不同RUNNINGjstack [pid]IN_NATIVEjstack -F [pid]、jstack -m [pid]为什么一个 IN_NATIVE 状态的线程不会阻止GC线程顺利达到SafePoint呢我在JDK源码及注释中找到了答案虽然处于IN_NATIVE状态的线程不会阻塞但是其在native调用返回后首先就会检查safepointRunning 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(11){}然后额外新建多个线程去开辟空间让其快速触发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 bughttps://docs.oracle.com/en/java/javase/20/troubleshoot/troubleshoot-process-hangs-and-loops.html#GUID-88307E36-5BA7-4EF7-B90D-5B8F028E7890Oracle官网文档提供hang死排查思路https://issues.apache.org/jira/browse/KAFKA-14063?jqlproject%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22解析message导致的OOMhttps://issues.apache.org/jira/browse/KAFKA-7863?jqlproject%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22JMX 导致的OOM问题我们项目也用到了JMX不过case不一样https://issues.apache.org/jira/browse/KAFKA-6777?jqlproject%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22经典JVM bugGC为了尽可能完成任务导致JVM假死的casehttps://issues.apache.org/jira/browse/KAFKA-14342?jqlproject%20%3D%20KAFKA%20AND%20text%20~%20%22OOM%22KafkaOffsetBackingStore引发的bug曾经一度怀疑是kafka的mm2引发的因为我们生产环境用到了mm2https://stackoverflow.com/questions/26140182/running-jmap-getting-unable-to-open-socket-file解释jstack、jmap命令执行时是否增加-F参数对应的执行过程不同https://hllvm-group.iteye.com/group/topic/41015JVM hang住所有线程BLOCKED包括GC线程Eden区100% 与我们case及其相近不过是修改GC源码引发的bughttps://stackoverflow.com/questions/36616126/jvm-hangs-after-migrating-to-jdk1-8-0-74JVM hangs after migrating to jdk1.8.0_74也是hang死的case不过没有定论https://stackoverflow.com/questions/54278053/why-java-safepoint-never-reached-thread-hang-safepoint-timeoutWhy Java safepoint never reached? Thread hang, safepoint timeouthttps://blog.csdn.net/qq_43799161/article/details/130967749JVM源码分析VMThread线程https://access.redhat.com/solutions/6240311红帽官网也是遇到hang死情况不过他们的卡点是SafepointSynchronize::beginhttps://www.jianshu.com/p/43bc97230299记一次线上JVM长时间STW之分析http://jcdav.is/2015/11/09/More-JVM-Signal-Tricks/一个小测试主动让JVM Stop The Worldhttps://blog.csdn.net/iter_zc/article/details/41892567SafePoint与线程阻塞https://www.infoq.cn/article/jvm-bug-thread一些关于GC的C代码导读https://github.com/rust-lang/cargo/issues/10007linux关于__GI___poll的bug发现