神秘现象:503错误峰值
在处理每秒数百万用户请求的大规模Java服务中,我们遇到了间歇性的负载均衡器超时峰值,导致向用户返回503响应。在负载下,部分Web服务器会停顿数秒,停止接受新连接,导致请求堆积和失败。唯一线索是这种行为与主机上另一个基于磁盘的缓存系统产生的高磁盘I/O周期相关。
关键证据:解读GC日志
经过数周调试,我们在垃圾回收日志中捕获了关键证据。典型的Young GC暂停应该在几十或几百毫秒内完成,但我们看到了:
|
|
乍看之下,这像是极其漫长的GC暂停。但关键洞察在[Times]部分:
- user=0.25 sys=0.05(总CPU时间:0.30秒):这是GC进程实际使用的CPU时间,GC算法本身非常快速高效
- real=15.35秒(实际时间):从暂停开始到结束在现实世界中经过的总时间
差异很明显:JVM处于Stop-the-World状态超过15秒,但实际工作(在CPU上)只用了0.3秒。在另外约15秒中,STW线程处于"off-CPU"状态,卡在等待状态。
根本原因:同步日志写入与磁盘争用
Young GC是一个"Stop-the-World"事件。JVM会暂停所有应用线程以安全地移动内存。我们发现这个GC操作的最后一个步骤是同步将日志条目写入GC日志文件。那个简单的write()系统调用成了杀手。
由于磁盘受到其他缓存进程的激烈争用,内核的I/O队列饱和。GC线程的日志写入(看似无害的操作)卡在该队列中,等待物理磁盘。由于JVM处于STW暂停状态,整个应用程序都被冻结,等待那一行日志被写入。
修复方法很简单:我们停止将GC日志写入那个有争用的磁盘。
两种解决方案
1. 文件系统级修复(我们的解决方案)
这是我们最初的解决方案。我们将GC日志路径从物理磁盘上的默认位置更改为RAM支持的文件系统。
方法:将日志输出指向tmpfs中的路径,如-Xloggc:/dev/shm/my-app-gc.log
工作原理:写入tmpfs不是真正的磁盘I/O。它们是内存到内存的复制,几乎是瞬时的。write()调用立即返回,STW暂停结束。
内存溢出问题:这是一个合理的担忧。将日志写入RAM理论上可能消耗所有可用内存并使服务器崩溃。我们通过使用JVM内置的日志轮换标志来缓解这个问题:
|
|
我们将GC日志的总内存使用量限制在可预测的120MB,消除了进程失控的风险。
权衡(缺点):
- 日志是临时的:
/dev/shm中的日志在每次系统重启或容器重启时都会丢失 - 丢失归档:此更改意味着日志不再被我们的集中式持久日志系统自动拾取
2. JVM级修复(现代方法)
多年来,tmpfs技巧是唯一的解决方案。最近,Amazon Corretto团队开发并贡献了一个正式的JVM功能来添加异步GC日志记录,并成为OpenJDK 17中的标准功能。
方法:在-Xlog标志中使用async装饰器:
|
|
工作原理:STW GC线程不再执行I/O。它将日志消息写入小的内存缓冲区,并立即恢复应用程序线程。然后,一个单独的低优先级后台线程负责将该缓冲区刷新到磁盘。
优点:
- 这是"官方"和预期的解决方案
- 不需要操作系统级技巧
- 日志写入标准文件路径,便于收集
缺点:
- 在极端突发场景中(对于GC日志不太可能),异步缓冲区可能填满,可能导致主线程停顿
- 在旧的Java部署中不可用
为什么这仍然重要
这个问题在容器时代重新出现。现代的"最佳实践"是让应用程序直接记录到stdout/stderr。但stdout不是一个神奇的虚空;它是一个管道。某些其他进程必须从管道的另一端读取。
这通常是容器运行时(如containerd)或日志代理(如Fluentd、Vector或Logstash)。如果该日志代理运行缓慢、配置错误或在其自己的网络或磁盘I/O上被阻塞,其读取缓冲区就会填满。这种反压会沿着管道向上传播,您的应用程序对stdout的下一个write()将会阻塞。如果JVM在STW暂停期间尝试将GC日志写入stdout,并且日志代理不堪重负,您将重新陷入相同的停顿。
关键要点
- real vs. user+sys是您的信号:当您在任何日志中看到高实际时间但低user + sys时间时,这不是CPU问题。这是I/O问题(磁盘、网络)或操作系统调度程序问题(CPU匮乏)
- 关键路径上不要执行I/O:永远不要在执行整个应用程序所依赖的线程上执行阻塞I/O,包括"简单"的日志记录
- 使用异步日志记录:对于现代JVM,使用
-XLog:async标志。这是将这种I/O移出关键路径的最干净的方法 - 对stdout保持警惕:在容器化世界中,记录到stdout仍然是阻塞I/O调用。确保集群的日志管道健壮且非阻塞,否则您可能会将日志延迟转变为应用程序范围的停顿