GC日志时间分析: user + sys < real

文章目录
  1. 1. 背景
  2. 2. 原因
    1. 2.1. 繁忙的I/O操作
    2. 2.2. 缺乏CPU资源

背景

在GC日志里,一条完整的GC日志记录最后,会带有本次GC所花费的时间,如下面这一条新生代GC:

[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), 0.0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

注意到日志中时间分为了三块:usersys,和 real,三者的区别和含义如下:

  • real:指的是在此次GC事件中所花费的总时间;
  • user:指的是CPU工作在用户态所花费的时间;
  • sys:指的是CPU工作在内核态所花费的时间。

更明确的定义可以参考StackOverflow上这一篇文章

user + sys 就是CPU花费的实际时间,注意这个值统计了所有CPU上的时间,如果进程工作在多线程的环境下,这个值是会超出 real 所记录的值的,即 user + sys >= real

对于GC事件来说,无论是 Minor GC 还是 Full GC 的过程,都存在并发的GC算法,如新生代的ParNew,老年代的ParallelOld,GC过程中工作负载是由多个线程共同完成的,这也就意味着使用这些GC算法时,GC日志中我们应该观察到:user + sys > real。譬如说:配置了ParNew且并发数为5的GC活动(-XX:+UseParNewGC -XX:ParallelGCThreads=5)中,如果user + sys的值为 2 seconds,那么 real 的时间 就近似为 400ms(2 seconds / 5)

场景1

[Times: user=11.53 sys=1.38, real=1.03 secs]

垃圾回收过程是通过并发执行,因此 user + sys 远大于 real

场景2

[Times: user=0.09 sys=0.00, real=0.09 secs]

因为使用了串行的垃圾回收期,所以时间应该是 userreal 相等。

场景3

[Times: user=0.20 sys=0.01, real=18.45 secs]

这是一个异常的示例,可以看到 real 所显示的时间 远 大于 user + sys

一般来说,如果观察到GC日志里多次出现了场景3所示的日志,这表明JVM的GC 过程存在某些问题(等待计算资源),原因可能是下面这两种

  • 繁忙的I/O操作
  • 缺乏CPU资源

原因

繁忙的I/O操作

当程序存在繁忙的I/O操作(网络IO或磁盘IO)时,会让 real 时间大幅上升。因为在记录GC日志的时候,你的程序进行了磁盘读写,如果同一时间其他IO操作较重,则此时GC事件会延迟,进而影响了最终的 real 的值。

注意,如果程序本身不存在的频繁的IO操作,同一机器上其他进程的频繁IO也会影响 real 的最终结果(可以参考这篇文章:Eliminating Large JVM GC Pauses Caused by Background IO Traffic

Linux环境下可以使用 sar 监视机器上的I/O,eg. sar -d -p 1,如果频繁的IO操作的确存在,可以通过下面两种方式改进:

  • 优化程序本身的IO操作逻辑;
  • 消除其他进程带来的IO影响。

缺乏CPU资源

当程序本身是CPU密集型应用,或机器上其他进程占用了大量的CPU计算资源,则有可能会出现分配不到 CPU cycles的情况,这会让程序挂起,GC所花费的实际时间也将远大于 user + sys 的值。

可以使用 top 命令观察一下 进程的CPU利用率,同时辅以Profiler工具统计一段时间内进程的状态分布。如果的确是CPU资源不足,解决方法无法下面几种:

  • 优化程序内部的线程使用,确保无冗余的线程配置;
  • 增加虚拟机或容器的CPU配置,提升机器总的计算能力。

当程序本身是 CPU 密集型应用,或机器上其他进程占用了大量的计算资源,则有可能会出现分配不到的情况,这会让程序挂起,所花费的时间也将远大于的值