java虚拟机小贴士之GC分析

打印日志

　　通过加入 -XX:+PrintGCDetails 参数则可以打印详细GC信息至控制台。参数-verbose:gc也是可以，但不够详细。通过加入-XX:+PrintGCDateStamps则可以记录GC发生的详细时间。通过加入 -Xloggc:/home/XX/gc/app_gc.log。可以把GC输出至文件，这对长时间服务器GC监控很有帮助。通过加入-XX:+DisableExplicitGC可以将System.gc()转为空操作。

日志分析

ParNew

　　通过加入-XX:+UseParNewGC参数指定新生代使用ParNew垃圾收集器。

2017-12-19T15:45:31.518-0800: 0.218: [GC (Allocation Failure) 2017-12-19T15:45:31.518-0800: 0.218: [ParNew: 31031K->4351K(39296K), 0.2660674 secs] 31031K->22453K(126720K), 0.2661635 secs] [Times: user=0.59 sys=0.05, real=0.27 secs]

　　2017-12-19T15:45:31.518-0800　GC发生的时间。　Allocation Failure表示gc的原因；ParNew表示是ParNew新手代收集器；31031K表示GC前的年轻代大小； 4351K表示GC后的年轻代大小；39296K年轻代的总大小。0.2660674本次回收的时间。

Parallel Scavenge

2017-12-18T20:54:09.544-0800: 2.988: [GC (Allocation Failure) [PSYoungGen: 33280K->400K(38400K)] 33280K->408K(125952K), 0.0008640 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

　　2017-12-18T20:54:09.544-0800 GC发生的时间。Allocation Failure表示gc的原因；PSYoungGen 表示是Parallel Scavenge新时代收集器；33280K 表示GC前的年轻代大小； 400K表示GC后的年轻代大小；38400K年轻代的总大小。33280K表示GC前的堆大小；408K表示GC后的堆大小；125952K表示堆的总大小0.0008640本次回收的时间。Times: user=0.00 sys=0.00, real=0.00 secs，表示内核执行用户时间，系统调用时间，和总时间。

CMS

　　通过加入-XX:+UseConcMarkSweepGC参数指定老年代使用CMS垃圾收集器。

2017-12-19T16:08:32.961-0800: 11.052: [GC (CMS Initial Mark) [1 CMS-initial-mark: 26710K(87424K)] 28716K(126720K), 0.0017267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-12-19T16:08:32.962-0800: 11.054: [CMS-concurrent-mark-start]
2017-12-19T16:08:33.041-0800: 11.133: [CMS-concurrent-mark: 0.079/0.079 secs] [Times: user=0.06 sys=0.01, real=0.08 secs] 
2017-12-19T16:08:33.041-0800: 11.133: [CMS-concurrent-preclean-start]
2017-12-19T16:08:33.043-0800: 11.134: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-12-19T16:08:33.043-0800: 11.134: [CMS-concurrent-abortable-preclean-start]
2017-12-19T16:08:33.555-0800: 11.647: [CMS-concurrent-abortable-preclean: 0.075/0.512 secs] [Times: user=0.15 sys=0.01, real=0.51 secs] 
2017-12-19T16:08:33.555-0800: 11.647: [GC (CMS Final Remark) [YG occupancy: 1939 K (39296 K)]2017-12-19T16:08:33.555-0800: 11.647: [Rescan (parallel) , 0.0038080 secs]2017-12-19T16:08:33.559-0800: 11.651: [weak refs processing, 0.0000223 secs]2017-12-19T16:08:33.559-0800: 11.651: [class unloading, 0.0002446 secs]2017-12-19T16:08:33.560-0800: 11.651: [scrub symbol table, 0.0004310 secs]2017-12-19T16:08:33.560-0800: 11.651: [scrub string table, 0.0001471 secs][1 CMS-remark: 32503K(87424K)] 34443K(126720K), 0.0047693 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2017-12-19T16:08:33.560-0800: 11.652: [CMS-concurrent-sweep-start]
2017-12-19T16:08:33.572-0800: 11.663: [CMS-concurrent-sweep: 0.011/0.011 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2017-12-19T16:08:33.572-0800: 11.663: [CMS-concurrent-reset-start]
2017-12-19T16:08:33.576-0800: 11.668: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

1.第一阶段初始标记

　　2017-12-19T16:08:32.961-0800: 11.052 CMS Initial Mark的开始时间。CMS Initial Mark：收集阶段，开始收集所有的GC Roots和直接引用到的对象；26710K当前老年代的使用容量；87424K老年代的总容量；28716K当前堆的使用容量；126720K当前堆的总容量；0.0017267 secs执行时间。

2.第二阶段并发标记

　　这个阶段会遍历整个老年代并且标记所有存活的对象，并发标记的特点是和应用程序线程同时运行。

　　2017-12-19T16:08:32.962-0800: 11.054并发标记时间；CMS-concurrent-mark-start并发标记开始；CMS-concurrent-mark: 0.079/0.079 secs并发标记执行时间；

3.第三阶段并发重新标记

　　前一个阶段在并行运行的时候，一些对象的引用已经发生了变化，在这个阶段，那些能够对那些对象到达的对象标记。

　　2017-12-19T16:08:33.041-0800: 11.133 并发重新标记时间； CMS-concurrent-preclean-start并发重新标记开始标志； CMS-concurrent-preclean: 0.002/0.002 secs并发重新标记执行时间。

4.第四阶段并发重复标记

　　这个阶段是重复的做相同的事情直到发生aboart的条件。

　　2017-12-19T16:08:33.043-0800: 11.134: 并发重新标记时间；CMS-concurrent-abortable-preclean-start并发重新标记开始标志； CMS-concurrent-abortable-preclean: 0.075/0.512 secs并发重新标记执行时间。

5.第五阶段最终标记

　　该阶段的任务是完成标记整个年老代的所有的存活对象。

　　2017-12-19T16:08:33.555-0800: 11.647: 并发重新标记时间；CMS Final Remark 最终标记； YG occupancy: 1939 K (39296 K) 年轻代当前占用容量情况；

　　2017-12-19T16:08:33.555-0800: 11.647: [Rescan (parallel) , 0.0038080 secs] 这个阶段，应用停止，完成最终标记

　　2017-12-19T16:08:33.559-0800: 11.651: [weak refs processing, 0.0000223 secs] 第一个子阶段；

　　2017-12-19T16:08:33.559-0800: 11.651: [class unloading, 0.0002446 secs] 第二个子阶段；

　　2017-12-19T16:08:33.560-0800: 11.651: [scrub symbol table, 0.0004310 secs]第三个子阶段

　　2017-12-19T16:08:33.560-0800: 11.651: [scrub string table, 0.0001471 secs]第四个子阶段

　　[1 CMS-remark: 32503K(87424K)] 34443K(126720K), 0.0047693 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

6.第六阶段并发清理

　　这个阶段的目的就是移除那些不用的对象。

　　2017-12-19T16:08:33.560-0800: 11.652:清理的时间；[CMS-concurrent-sweep-start] 开始清理标志

　　 2017-12-19T16:08:33.572-0800: 11.663:清理的时间 [CMS-concurrent-sweep: 0.011/0.011 secs] 清理花费的时间[Times: user=0.01 sys=0.00, real=0.01 secs]

7.第七阶段重置

　　重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用。

　　2017-12-19T16:08:33.572-0800: 11.663: [CMS-concurrent-reset-start]

　　2017-12-19T16:08:33.576-0800: 11.668: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

Full GC

2017-12-19T14:20:21.524-0800: 0.745: [Full GC (Ergonomics) [PSYoungGen: 5120K->0K(71680K)] [ParOldGen: 98922K->96623K(207872K)] 104042K->96623K(279552K), [Metaspace: 2635K->2635K(1056768K)], 0.8495748 secs] [Times: user=1.81 sys=0.04, real=0.85 secs]

　　2017-12-19T14:20:21.524-0800: 0.745: GC发生的时间。PSYoungGen 表示是Parallel Scavenge新时代收集器；5120K表示GC前的年轻代大小； 0K表示GC后的年轻代大小； 71680K年轻代的总大小。ParOldGen表示是Parallel Old收集器；98922K表示GC前的老年代大小；96623K表示GC前的老年代大小；207872K表示老年代总大小；104042K表示GC前的总大小；96623K表示GC后的总大小；279552K表示总大小；