如何排查G1 GC突发长停顿（real时间远高于user/sys）的原因？

我正在排查G1 GC偶尔出现10-15秒长停顿的原因，大部分GC停顿时间较短，但偶尔会突然飙升。分析GC日志发现，某次G1 Evacuation Pause（young）耗时8.96秒，其中real时间（8.97秒）显著高于user时间（0.27秒）和sys时间（0.01秒），需要找出问题根源。

本次GC日志详情 #

2023-06-08T05:32:10.709+0000: 593903.305: [GC pause (G1 Evacuation Pause) (young), 8.9649309 secs]
   [Parallel Time: 8963.5 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 593903305.3, Avg: 593903306.2, Max: 593903308.9, Diff: 3.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 2.4, Max: 3.3, Diff: 3.2, Sum: 9.6]
      [Update RS (ms): Min: 5.3, Avg: 5.6, Max: 6.0, Diff: 0.7, Sum: 22.3]
         [Processed Buffers: Min: 9, Avg: 62.8, Max: 84, Diff: 75, Sum: 251]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 8854.5, Avg: 8904.6, Max: 8954.6, Diff: 100.1, Sum: 35618.3]
      [Termination (ms): Min: 0.0, Avg: 49.9, Max: 100.4, Diff: 100.4, Sum: 199.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 8959.9, Avg: 8962.5, Max: 8963.5, Diff: 3.6, Sum: 35850.2]
      [GC Worker End (ms): Min: 593912268.7, Avg: 593912268.7, Max: 593912268.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 132.0M(132.0M)->0.0B(145.0M) Survivors: 21.0M->8192.0K Heap: 690.6M(3072.0M)->559.1M(3072.0M)]
 [Times: user=0.27 sys=0.01, real=8.97 secs] 
2023-06-08T05:32:19.674+0000: 593912.270: Total time for which application threads were stopped: 8.9664744 seconds, Stopping threads took: 0.0001051 seconds

关键日志解读 #

• Object Copy阶段是核心耗时点：该阶段平均耗时8904.6ms，占整个Parallel Time的99%以上，说明对象复制过程中出现了严重延迟。
• real时间远高于user+sys时间：这种现象表明GC线程大部分时间处于等待状态，而非执行计算或系统调用，指向系统/硬件层面的资源瓶颈。

可能的原因及排查方向 #

• 磁盘I/O阻塞：若JVM堆所在存储设备（或交换分区）出现I/O瓶颈，会导致内存页交换缓慢，拖慢对象复制。需检查GC时段的磁盘IO使用率、等待队列长度。
• CPU资源被抢占：GC线程可能被其他高优先级进程抢占CPU，导致无法持续执行。查看GC时段的系统CPU负载、进程CPU占用情况，确认是否有其他进程占用大量资源。
• 内存带宽不足：对象复制需要频繁读写内存，若服务器内存带宽被其他进程耗尽，会导致内存操作延迟飙升。可通过性能工具监控内存带宽使用率。
• 硬件故障：内存模块、存储控制器等硬件故障可能导致间歇性内存访问延迟，需通过硬件诊断工具排查。
• JVM参数配置问题：比如-XX:G1MaxNewSizePercent设置过大，导致Young区单次回收对象过多；当前GC Workers为4，若服务器CPU核心数较多，可尝试调整-XX:ParallelGCThreads增加GC线程数。

验证建议 #

1. 同步监控GC发生时段的系统指标（CPU、磁盘IO、内存带宽），定位是否存在资源饱和点。
2. 调整JVM参数：适当降低Young区最大比例，增加GC线程数，观察长停顿是否复现。
3. 检查服务器硬件健康状态，排除硬件故障可能性。

内容的提问来源于stack exchange，提问作者sweet_summer_child