解决神秘的 JVM Safepoint 问题：从问题到解决方案的探索之旅
#

最近，我们在生产环境中遇到了一个特殊问题：某些高量日志应用在每小时 05 分钟触发的每小时日志同步任务时会长时间冻结。通过仔细检查我们的 safepoint 日志（通过启动参数 -Xlog:safepoint=trace:file=${LOG_PATH}/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M 启用，并利用 Java 17 的 -Xlog:async 进行异步日志记录以防止 JVM 日志输出阻塞进程），我们发现所有事件都是由以下原因引起的：

GC 日志：-Xlog:gc*=debug:file=${LOG_PATH}/gc%t.log:utctime,level,tags:filecount=50,filesize=100M
JIT 编译日志：-Xlog:jit+compilation=info:file=${LOG_PATH}/jit_compile%t.log:utctime,level,tags:filecount=10,filesize=10M
禁用堆栈跟踪省略：这仅省略内部 JDK 异常，如 NullPointerException：-XX:-OmitStackTraceInFastThrow，我们已经优化了这一点以处理高错误量期间过多堆栈跟踪输出的性能压力

实施这些配置后，我们的应用表现出了一个奇怪的问题，有三种不同的表现，但都有一个共同特征：异常长的 safepoint 持续时间。

1. Safepoint 日志显示所有线程到达 safepoint 的等待时间极长（到达 safepoint：超过 25 秒）

2. Safepoint 日志显示由 GC 导致的延长 safepoint 持续时间（在 safepoint：超过 37 秒）

检查 GC 日志，我们注意到 Heap before GC invocations 和堆结构输出日志之间存在显著延迟：

3. 另一个由于 GC 导致 safepoint 持续时间延长的案例，但具有不同的日志间隔模式（超过 29 秒） GC 日志显示某些堆结构输出日志存在大量延迟：

问题调查
#

当 Java 应用线程集体处于 safepoint 时，它们变得完全不活跃。这意味着依赖应用线程的监控 - 如通过 Spring Actuator 的 Prometheus 端点和 Skywalking 插桩的外部 JVM 监控 - 对实际问题变得盲目。这些监控工具只显示在 safepoint 期间调用的方法花费异常长的时间，但这并不表明这些方法本身是瓶颈。

我们需要依赖内部 JVM 监控机制，如 JVM 日志和 JFR（Java Flight Recording）进行正确诊断。我们还使用了 async_profiler (https://github.com/jvm-profiling-tools/async-profiler/)，因为我们观察到在问题期间，进程自身的 CPU 使用率（不是机器的，而是特指这个进程）会急剧飙升：

奇怪的是，在问题时间段通过 async_profiler 检查 CPU 使用率时，我们发现除了预期模式外：

最值得注意的是，在 safepoint 期间，日志记录似乎被中断 - 这是一个极其罕见的情况。以下是这个观察很重要的原因：

对于第一种现象（所有线程进入 safepoint 的等待时间延长），我们通常期望连续输出日志，指示哪些线程尚未进入 safepoint，如 JVM 源代码中引用的：

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

然而，在我们的第一种现象中，我们没有观察到任何日志指示哪个特定线程导致了延长的 safepoint 进入时间。

对于第二种现象，JFR 分析没有显示任何特别耗时的 GC 阶段：

对于第三种现象，检查 JVM 源代码显示，在两个有大量间隔的日志之间，除了日志记录本身，几乎什么都没有发生。此外，所有问题时间戳都发生在每小时的 05 分钟附近。咨询我们的运维团队后，我们了解到这个时间与前一小时的日志文件删除和 EFS 同步同时发生（我们每小时生成一个日志文件），涉及大量文件 I/O 操作（由于我们使用云服务，这可能涉及 EFS 类型的 NFS 或网络对象存储，而不是传统的磁盘 I/O）。过多的文件 I/O 是否会阻塞 JVM 日志输出，从而冻结整个 JVM？

为什么 JVM 日志输出会阻塞所有应用线程？如果 JVM 线程在 safepoint 外输出日志时卡住，它只会阻塞自己，不会阻塞所有应用线程。然而，如果这发生在 safepoint 期间，当所有应用线程已经暂停时，卡住的 JVM 线程输出日志可能会阻止所有线程进入 safepoint 或导致延长的 safepoint 持续时间。对于第一种现象，输出 JVM 日志的线程（不是应用日志 - 应用日志输出通常涉及原生文件 I/O 调用，这些调用被认为处于 safepoint 状态，不会造成问题，如我的另一篇文章中详述：JVM 相关 - SafePoint 和 Stop The World 完整指南：https://zhuanlan.zhihu.com/p/161710652）卡住，阻止该线程进入 safepoint。对于现象二和三，GC 线程在输出 JVM 日志时卡住，阻止 GC 完成。

让我们首先检查 JVM 源代码，确认卡住的 JVM 日志输出是否确实会阻塞 JVM。