JVM之ParNew和CMS日志分析

今天这篇文章主要是对生产环境中（Java7）常用的两种垃圾收集器（ParNew：年轻代，CMS：老年代）从日志信息上进行分析，做一下总结，这样当我们在排查相应的问题时，看到 GC 的日志信息，不会再那么陌生，能清楚地知道这些日志是什么意思，GC 线程当前处在哪个阶段，正在做什么事情等。

ParNew 收集器

ParNew 收集器是年轻代常用的垃圾收集器，它采用的是复制算法，youngGC 时一个典型的日志信息如下所示：

2018-04-12T13:48:26.134+0800: 15578.050: [GC2018-04-12T13:48:26.135+0800: 15578.050: [ParNew: 3412467K->59681K(3774912K), 0.0971990 secs] 9702786K->6354533K(24746432K), 0.0974940 secs] [Times: user=0.95 sys=0.00, real=0.09 secs]

依次分析一下上面日志信息的含义：

• 2018-04-12T13:48:26.134+0800：Mirror GC 发生的时间；
• 15578.050：GC 开始时，相对 JVM 启动的相对时间，单位时秒，这里是4h+；
• ParNew：收集器名称，这里是 ParNew 收集器，它使用的是并行的 mark-copy 算法，GC 过程也会 Stop the World；
• 3412467K->59681K：收集前后年轻代的使用情况，这里是 3.25G->58.28M；
• 3774912K：整个年轻代的容量，这里是 3.6G；
• 0.0971990 secs：Duration for the collection w/o final cleanup.
• 9702786K->6354533K：收集前后整个堆的使用情况，这里是 9.25G->6.06G;
• 24746432K：整个堆的容量，这里是 23.6G；
• 0.0974940 secs：ParNew 收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代开销、垃圾收集周期结束一些最后的清理对象等的花销）；

对于 [Times: user=0.95 sys=0.00, real=0.09 secs]，这里面涉及到三种时间类型，含义如下：

• user：GC 线程在垃圾收集期间所使用的 CPU 总时间；
• sys：系统调用或者等待系统事件花费的时间；
• real：应用被暂停的时钟时间，由于 GC 线程是多线程的，导致了 real 小于 (user+real)，如果是 gc 线程是单线程的话，real 是接近于 (user+real) 时间。

CMS 收集器

CMS 收集器是老年代经常使用的收集器，它采用的是标记-清楚算法，应用程序在发生一次 Full GC 时，典型的 GC 日志信息如下：

2018-04-12T13:48:26.233+0800: 15578.148: [GC [1 CMS-initial-mark: 6294851K(20971520K)] 6354687K(24746432K), 0.0466580 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
2018-04-12T13:48:26.280+0800: 15578.195: [CMS-concurrent-mark-start]
2018-04-12T13:48:26.418+0800: 15578.333: [CMS-concurrent-mark: 0.138/0.138 secs] [Times: user=1.01 sys=0.21, real=0.14 secs]
2018-04-12T13:48:26.418+0800: 15578.334: [CMS-concurrent-preclean-start]
2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-preclean: 0.056/0.057 secs] [Times: user=0.20 sys=0.12, real=0.06 secs]
2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-abortable-preclean-start]
2018-04-12T13:48:29.989+0800: 15581.905: [CMS-concurrent-abortable-preclean: 3.506/3.514 secs] [Times: user