背景：突如其来的服务中断
2025年12月，我们负责的电商促销系统在流量高峰期间频繁出现15秒以上的服务中断。监控显示，每次中断都伴随JVM的STW（Stop-The-World）停顿，而GC日志显示Full GC耗时仅0.8秒。这让我们陷入困惑：究竟是什么原因导致如此长时间的停顿？
排查过程：从GC日志到系统IO
GC日志分析
通过-Xlog:gc*参数开启详细日志，我们发现每次长停顿都发生在GC日志写入阶段。关键日志片段：
text
Copy Code
[Full GC (System.gc()) 0.8s]
[GC log write blocked for 14.2s]
系统IO监控
iostat数据显示，日志所在磁盘的await指标在停顿期间飙升至2000ms以上，而GC日志文件所在的HDD磁盘IOPS已饱和。这让我们怀疑是磁盘写入阻塞了JVM线程。
实验验证
我们临时将GC日志重定向到tmpfs内存文件系统，停顿时间立即降至毫秒级。这证实了我们的猜想：GC日志写入被磁盘IO阻塞。
根本原因：日志写入与GC的致命耦合
JVM的同步写入机制
JVM默认采用同步方式写入GC日志，即使使用-XX:+UseGCLogFileRotation参数，在日志滚动时仍会触发同步写操作。在HDD磁盘上，这种操作在IO繁忙时可能耗时数秒。
GC停顿的放大效应
当GC线程等待日志写入完成时，所有应用线程都被阻塞在Safepoint等待GC完成。这种等待会线性放大停顿时间，最终导致服务中断。
解决方案：三重优化策略
日志分离
将GC日志与业务日志分离，使用独立SSD磁盘：
bash
Copy Code
-Xlog:gc:file=/data/gc_logs/gc_%t.log:time,tags:filecount=10,filesize=100M
异步日志框架
对于业务日志，采用Log4j2的AsyncLogger：
xml
Copy Code
<AsyncLogger name="com.example" level="info" includeLocation="false">
<AppenderRef ref="File"/>
</AsyncLogger>
JVM参数优化
添加关键参数减少GC日志影响：
bash
Copy Code
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/gc_logs/gc.log
预防措施：建立IO监控体系
实时监控
在Prometheus中配置磁盘IO告警：
yaml
Copy Code
alert: DiskIOHighLatency
expr: rate(node_disk_io_time_seconds_sum[5m]) > 0.8
压力测试
在预发环境模拟大流量场景，验证GC日志写入性能：
bash
Copy Code
stress-ng --io 4 --io-bytes 1G --timeout 60s
日志审计
定期检查GC日志文件大小和IO延迟：
bash
Copy Code
find /data/gc_logs -name "gc_*.log" -size +100M
经验总结
警惕隐藏的IO依赖
JVM的日志系统看似简单，实则可能成为性能瓶颈。务必对日志IO路径进行压力测试。
分离关键路径
将GC日志、业务日志、系统日志分别存储到不同磁盘，避免相互影响。
监控先行
建立完善的IO监控体系，包括磁盘队列长度、IO延迟、吞吐量等关键指标。
定期演练
每季度进行全链路压测，特别关注日志系统在高负载下的表现。
这次故障让我们深刻认识到，在分布式系统中，任何看似简单的组件都可能成为性能瓶颈。作为SRE，我们需要以更系统化的方式思考问题，建立多层防御机制，确保系统稳定性。