GC日志时间分析

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

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

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

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

  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]

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

场景3

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

  这是一个异常的示例,可以看到 real 所显示的时间 远 大于 user + sys。一般来说,如果观察到GC日志里多次出现了场景3所示的日志,这表明JVM的GC 过程存在某些问题(等待计算资源),原因可能是下面这两种:

  •   频繁的IO操作
  •   缺乏CPU资源

繁忙的I/O操作

  当程序存在繁忙的I/O操作(网络IO或磁盘IO)时,会让 real 时间大幅上升。因为在记录GC日志的时候,你的程序进行了磁盘读写,如果同一时间其他IO操作较重,则此时GC事件会延迟,进而影响了最终的 real 的值。注意,如果程序本身不存在的频繁的IO操作,同一机器上其他进程的频繁IO也会影响 real 的最终结果。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配置,提升机器总的计算能力。
posted @ 2018-04-04 15:44  木易森林  阅读(2062)  评论(0编辑  收藏