JVM 输出 GC 日志导致 JVM 卡住

本系列是 我TM人傻了 系列第七期[捂脸]，往期精彩回顾：

• 升级到Spring 5.3.x之后，GC次数急剧增加，我TM人傻了：https://zhuanlan.zhihu.com/p/397042565
• 这个大表走索引字段查询的 SQL 怎么就成全扫描了，我TM人傻了：https://zhuanlan.zhihu.com/p/397271448
• 获取异常信息里再出异常就找不到日志了，我TM人傻了：https://zhuanlan.zhihu.com/p/398521426
• spring-data-redis 连接泄漏，我 TM 人傻了：https://zhuanlan.zhihu.com/p/404912877
• Spring Cloud Gateway 没有链路信息，我 TM 人傻了：https://zhuanlan.zhihu.com/p/413589417
• Spring Cloud Gateway 雪崩了，我 TM 人傻了：https://zhuanlan.zhihu.com/p/414705493

最近，我们升级了 Java 17。后来，我们的 k8s 运维团队为了优化我们的应用日志采集，将我们所有 pod （你可以理解为一个 Java 微服务进程）的 JVM 日志都统一采集到同一个 AWS 的 EFS 服务（EFS 是 Elastic File System 的缩写，弹性块文件存储系统，底层是 NFS + S3 对象存储集群），我们对于 JVM 日志配置包括以下几个：

1. GC日志：-Xlog:gc*=debug:file=${LOG_PATH}/gc%t.log:utctime,level,tags:filecount=50,filesize=100M
2. JIT 编译日志：-Xlog:jit+compilation=info:file=${LOG_PATH}/jit_compile%t.log:utctime,level,tags:filecount=10,filesize=10M
3. Safepoint 日志：-Xlog:safepoint=trace:file=${LOG_PATH}/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M
4. 关闭堆栈省略：这个只会省略 JDK 内部的异常，比如 NullPointerException 这种的：-XX:-OmitStackTraceInFastThrow，我们应用已经对于大量报错的时候输出大量堆栈导致性能压力的优化，参考：https://zhuanlan.zhihu.com/p/428375711

JVM 统一日志配置请参考：https://zhuanlan.zhihu.com/p/111886882

在这样做之后，我们的应用出现这样一个奇怪的问题，这个问题有三种不同的现象，统一的表现是处于安全点的时间特别特别长：

1.通过 safepoint 日志看出来，等待所有线程进入安全点的时间特别长（Reaching safepoint：25s多）

2.通过 safepoint 日志看出来，还有处于 safepoint 时间过长的，并且原因是 GC（At safepoint: 37s多）

查看 GC 日志，Heap before GC invocations 与输出堆结构的日志间隔了很久：

3.另一种处于 safepoint 时间过长的，原因也是 GC，但是间隔日志的地方不一样（29s多）

查看 GC 日志，输出堆结构的日志某些间隔了很久：

问题定位

首先，Java 应用线程整体处于 safepoint，这时候应用线程什么都做不了，所以依赖应用线程的监控即通过 JVM 外部监控，例如 spring actuator 暴露的 prometheus 接口，以及 Skywalking 插桩监控，是什么都看不到的，只会看到出于安全点时调用的这些方法时间特别长，但是并不是这些方法真的有瓶。

需要通过 JVM 内部线程的监控机制，例如 JVM 日志，以及 JFR（Java Flight Recording）来定位。还有就是通过 async_profiler (https://github.com/jvm-profiling-tools/async-profiler/)，因为我们发现，在出问题的时候，进程本身的 CPU 占用（注意不是机器的，是这个进程的）也会激增：

但是非常奇怪的是，通过 async_profiler 查看 CPU 占用，发现出问题的时间段，除了：

并且在处于安全点的期间，日志也是被中断了一样，这是非常少见的，为什么这么说，请看下面分析：

针对现象一，等待所有线程进入 safepoint 时间特别长，这个一般会不断输出等待哪个线程没有进入安全点的日志，参考 JVM 源码：

https://github.com/openjdk/jdk/blob/master/src/hotspot/share/runtime/safepoint.cpp

但是现象一中我们并没有看到因为哪个线程导致进入 safepoint 时间过长。

针对现象二，通过 JFR，也没看出 GC 的哪个阶段耗时很长：

针对现象三，通过查看 JVM 源码发现，输出这两个间隔很大的日志的代码之间，没有做任何的事情，只是打日志。并且查看所有出异常的时间点，都是每个小时的 05 分左右，询问运维知道在这个时间，会进行上一小时日志文件的移出与与 EFS 同步（我们一个小时生成一个日志文件），会有大量文件 IO（由于底层使用的是云服务，也许并不是磁盘，而是 EFS 这种 NFS 或者网络对象存储）。会不会是文件 IO 太大导致 JVM 日志输出堵住导致 JVM 卡住呢？

为啥 JVM 日志输出会导致 JVM 所有应用线程卡住，假设 JVM 某个线程输出日志卡住了，倘若没有处于 safepoint，那么不会卡住所有应用线程，只会卡住它自己。但是如果处于 safepoint，所有应用线程本身就被暂停了，如果这个时候某个 JVM 线程输出日志卡住，那么可能造成迟迟不能所有线程进入安全点，或者所有处于安全点时间过长。对应现象一，某个线程输出的是 JVM 日志而不是应用日志（输出应用日志一般是涉及文件 IO 原生调用，处于原生调用直接就算进入了安全点，不会有影响，请参考我的另一篇文章：JVM相关 - SafePoint 与 Stop The World 全解：

https://zhuanlan.zhihu.com/p/161710652），输出 JVM 日志卡住导致这个线程迟迟没有进入安全点。针对现象二三，都是 GC 线程输出 JVM 日志卡住导致 GC 迟迟不结束。

首先通过 JVM 源码确认下 JVM 日志输出卡住是否会阻塞 JVM。

JVM 输出 JVM 日志源码分析

我们使用的是 Java 17，Java 17 之前没有异步 JVM 日志输出。所以待会的源码分析请忽略异步日志的代码，这样就是 Java 17 前的日志输出：

https://github.com/openjdk/jdk/blob/mast

通过这里的代码可以看出，如果输出文件 IO 卡住，这里的 flush 是会卡住的。同时，会有短暂的 CPU 激增，因为刷入等待的策略应该是 CPU 空转等待一段时间之后进入阻塞。

那么我们换成异步日志怎么样？异步日志有哪些参数呢？ JVM 异步日志是 Java 17 引入的，对应的 ISSUE 是：https://bugs.openjdk.org/browse/JDK-8229517，其中的关键，在于这两个参数：

通过 -Xlog:async 启用 JVM 异步日志，通过 -XX:AsyncLogBufferSize= 指定异步日志缓冲大小，这个大小默认是 2097152 即 2MB。异步日志的原理是：

修改参数为异步日志，问题大幅度缓解，但是并没完全解除，进一步定位

我们修改日志为异步日志，加入启动参数: -Xlog:async，-XX:AsyncLogBufferSize=4194304。之后观察，问题得到大幅度缓解：

er/src

但是还是在某一个实例上出现了一次问题，查看现象，与之前的不同了，通过 safepoint 日志看，是某个线程一直 running 不愿意不进入 safepoint：

那么这个线程在干什么呢？通过 jstack 看一下这个线程是什么线程：

这是一个定时刷新微服务实例列表的线程，代码对于 WebFlux 的使用并不标准：

这样使用异步代码，可能带来 JIT 优化错误（正确的用法调用很频繁，这个错误用法调用也很频繁，导致 JIT C2 不断优化与去优化），查看 JFR 发现这段时间也有很多 JIT 去优化：

这样可能导致安全点缺失走到 IO 不断空转等待很久的问题，需要改成正确的用法：

修改好之后，迟迟不进入 safepoint 的问题消失。

/hotspot/share/logging/logFileStreamOutput.cpp