SRE 踩坑记：JVM 暂停竟然是因为日志

在高性能计算领域，我们习惯于在代码、算法或基础设施中寻找瓶颈。但我遇到过的最棘手的问题却不在这些方面。那是Java虚拟机（JVM）的垃圾回收器与服务器磁盘之间一种无形的交互，导致一个每秒处理数百万请求的服务出现了15秒以上的全局暂停（STW）。

503 突增

我当时正在处理一个大规模的Java服务，该服务每秒要处理数百万用户请求。这个系统是为极高的吞吐量而设计的，但我们却深受负载均衡器间歇性超时峰值的困扰，这导致向用户返回了503响应。

我们发现，在负载情况下，一部分Web服务器会停滞并停止接受新连接数秒，导致请求堆积并失败。唯一的线索是，这种行为与大量磁盘I/O的时段相关，而这些磁盘I/O是同一主机上另一个基于磁盘的缓存系统产生的。

确凿证据：解读GC日志

经过数周的调试，我们终于在垃圾回收日志中找到了“确凿证据”。一次典型的新生代垃圾回收停顿时间应该在几十或几百毫秒。但我们看到的情况是这样的：

/* by yours.tools - online tools website : yours.tools/zh/json2cs.html */ [timestamp]: 184512.789: [GC [PSYoungGen: 1058042K->17224K(1069568K)] 3112024K->2018456K(3258112K), 15.3495220 secs] [Times: user=0.25 sys=0.05, real=15.35 secs]

乍一看，这似乎是一个长得离谱的垃圾回收暂停。但“啊哈！”的时刻出现在/* by yours.tools - online tools website : yours.tools/zh/json2cs.html */ [Times]部分：

• user=0.25 sys=0.05（总CPU时间：0.30秒）：这是垃圾回收（GC）进程使用的实际CPU时间。垃圾回收算法本身快得令人难以置信且效率很高。
• real=15.35 secs（挂钟时间）：这是从暂停开始到暂停结束在现实世界中经过的总时间。

这种差异十分明显：JVM处于全局停顿状态超过15秒，但实际（占用CPU）运行的时间仅为0.3秒。在其余约15秒内，STW线程处于“脱离CPU”状态，陷入了等待状态。

年轻代GC是一种“Stop-the-World”事件。JVM实际上会暂停所有应用线程，以安全地移动内存。我们发现，这个GC操作的最后一步是将日志条目同步写入GC日志文件。那个简单的write()系统调用就是问题所在。由于磁盘受到其他缓存进程的激烈争用，内核的I/O队列已饱和。GC线程的日志写入——一个看似无害的操作，在该队列中陷入停滞，等待物理磁盘。而且由于JVM处于STW暂停状态，整个应用程序都被冻结，等待那一行日志写入完成。

修复方法很简单：我们不再将GC日志写入那个竞争激烈的磁盘。

解决方案

这个基本问题，即一个关键的、阻塞的线程在等待输入/输出。以下是解决这个问题的两种主要方法。

1. 文件系统级修复（我们的解决方案）

这是我们最初的解决方案。我们将GC日志路径从物理磁盘上的默认位置更改为内存支持的文件系统。

方式：我们将日志输出（例如，-Xloggc:/var/log/my-app/gc.log）指向tmpfs中的一个路径，例如-Xloggc:/dev/shm/my-app-gc.log。

工作原理：写入tmpfs并非真正的磁盘输入/输出操作。它们是内存到内存的复制，几乎是瞬时完成的。write()调用会立即返回，从而结束STW暂停。

内存溢出怎么办？这是一个合理的担忧。理论上，将日志写入内存可能会耗尽所有可用内存并导致服务器崩溃。我们通过使用JVM的内置日志轮转标志来缓解此问题。通过设置：

-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=6 -XX:GCLogFileSize=20M

我们将垃圾回收日志的总内存使用量限制在可预测的120MB，从而消除了进程失控的风险。

缺点：

• 日志是临时的：/dev/shm中的日志会在每次系统重启或容器重启时丢失。
• 归档功能丢失：这一变更意味着日志不再被我们的集中式持久化日志系统自动收集。如果仍需持久化，则需要配置单独的日志传输代理（如边车代理）。

2. JVM级修复（现代方法）

多年来，tmpfs这种权宜之计是 唯一 的解决方案。最近，亚马逊 Corretto 团队开发并贡献了一项正式的 JVM 功能，用于添加异步 GC 日志记录，该功能已成为 OpenJDK 17 中的标准功能。

方法：将async修饰符用于您的-Xlog标志。

-Xlog:async -XX:AsyncLogBufferSize=100M

其工作原理：STW GC线程不再执行I/O操作。它会将日志消息写入一个小型的内存缓冲区，并立即恢复应用线程。随后，一个独立的低优先级后台线程负责将该缓冲区的内容刷新到磁盘。

优点：

• 这是“官方”且期望的解决方案。
• 无需操作系统级别的技巧。
• 日志写入标准文件路径，便于收集。

缺点：

• 在极端突发场景下（对于GC日志来说不太可能），异步缓冲区可能会被填满，这可能导致主线程停滞。
• 在较旧的Java部署中不是一个选项

为何这仍然重要

在容器时代，这个问题再次出现。现代的“最佳实践”是让应用程序直接将日志输出到stdout/stderr。但stdout并非一个神奇的虚无空间，它是一个管道。必须有其他进程从该管道的另一端进行读取。

这通常是容器运行时（如containerd）或日志代理（如Fluentd、Vector或Logstash）。如果该日志代理运行缓慢、配置错误，或者它自身的网络或磁盘I/O出现阻塞，其读取缓冲区就会被填满。这种背压会沿着管道向上传递，导致应用程序下一次对stdout执行write()操作时会阻塞。如果JVM在STW暂停期间尝试将GC日志写入stdout，而日志代理又不堪重负，那么你将会再次陷入同样的停滞状态。

核心要点

1. real与user+sys是你的信号：当你在任何日志中看到较高的real时间但较低的user+sys时间时，这不是CPU问题。而是I/O问题（磁盘、网络）或操作系统调度程序问题（CPU饥饿）。
2. 关键路径上无输入/输出操作：切勿在整个应用程序所依赖的线程上执行阻塞性输入/输出操作，包括“简单的”日志记录。
3. 使用async日志记录：对于现代JVM，使用-XLog:async标志。这是将此I/O从关键路径移开的最简洁方法。
4. 要警惕stdout：在容器化的世界中，向stdout记录日志仍然是一个阻塞式I/O调用。要确保你的集群日志管道既稳健又非阻塞，否则你可能会将日志记录延迟变成整个应用程序的停滞。

原文链接：https://dzone.com/articles/the-jvm-pause-that-wasnt-a-war-story