JVM暂停疑云：日志问句引风波

在高性能计算领域，我们习惯于在代码、算法或基础设施中寻找瓶颈。但我遇到过的最棘手的问题却不在这些方面。那是Java虚拟机（JVM）的垃圾回收器与服务器磁盘之间一种无形的交互，导致一个每秒处理数百万请求的服务出现了15秒以上的全局暂停（STW）。 503 突增 我当时正在处理一个大规模的Java服务，该服务每秒要处理数百万用户请求。这个系统是为极高的吞吐量而设计的，但我们却深受负载均衡器间歇性超时峰值的困扰，这导致向用户返回了503响应。 我们发现，在负载情况下，一部分Web服务器会停滞并停止接受新连接数秒，导致请求堆积并失败。唯一的线索是，这种行为与大量磁盘I/O的时段相关，而这些磁盘I/O是同一主机上另一个基于磁盘的缓存系统产生的。 确凿证据：解读GC日志 经过数周的调试，我们终于在垃圾回收日志中找到了“确凿证据”。一次典型的新生代垃圾回收停顿时间应该在几十或几百毫秒。但我们看到的情况是这样的： [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] 乍一看，这似乎是一个长得离谱的垃圾回收暂停。但“啊哈！”的时刻出现在[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操作。它会将日志消息写入一个小型的内存缓冲区，并立即恢复应用线程。随后，一个独立的低优先级后台线程负责将该缓冲区的内容刷新到磁盘。 优点： 这是“官方”且期望的解决方案。