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配置，提升机器总的计算能力。

每天进步一点点