CMS gc日志

https://blogs.oracle.com/poonam/understanding-cms-gc-logs
CMS执行过程

以下为一段GC日志分析
2018-04-09T09:08:58.551+0800: 4902223.804: [GC (CMS Initial Mark) [1 CMS-initial-mark: 18211959K(24254912K)] 18373886K(26018496K), 0.0046721 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
初始标记(CMS-initial-mark)阶段，标记由根可以直接到达的对象，标记期间整个应用线程会暂停。
老年代容量为24254912K，CMS 回收器在空间占用达到18211959K时被触发。开始使用CMS回收器进行老年代回收。
2018-04-09T09:08:58.556+0800: 4902223.809: Total time for which application threads were stopped: 0.0085825 seconds, Stopping threads took: 0.0002505 seconds
2018-04-09T09:08:58.556+0800: 4902223.809: [CMS-concurrent-mark-start]
开始并发标记(concurrent-mark-start) 阶段，在第一个阶段被暂停的线程重新开始运行，由前阶段标记过的对象出发，所有可到达的对象都在本阶段中标记。
2018-04-09T09:08:59.204+0800: 4902224.457: [CMS-concurrent-mark: 0.648/0.648 secs] [Times: user=4.12 sys=0.01, real=0.64 secs]
并发标记阶段结束，占用0.648秒CPU时间，0.648秒墙钟时间(也包含线程让出CPU给其他线程执行的时间)
2018-04-09T09:08:59.204+0800: 4902224.457: [CMS-concurrent-preclean-start]
开始预清理阶段,预清理也是一个并发执行的阶段。在本阶段,会查找前一阶段执行过程中,从新生代晋升或新分配或被更新的对象。通过并发地重新扫描这些对象，预清理阶段可以减少下一个stop-the-world重新标记阶段的工作量。
2018-04-09T09:08:59.491+0800: 4902224.744: [CMS-concurrent-preclean: 0.286/0.287 secs] [Times: user=0.64 sys=0.02, real=0.29 secs] 预清理阶段费时0.286秒CPU时间，0.287秒墙钟时间。
2018-04-09T09:08:59.491+0800: 4902224.744: [CMS-concurrent-abortable-preclean-start]
2018-04-09T09:09:00.499+0800: 4902225.752: [CMS-concurrent-abortable-preclean: 1.005/1.008 secs] [Times: user=3.84 sys=0.05, real=1.01 secs]
2018-04-09T09:09:00.503+0800: 4902225.756: [GC (CMS Final Remark) [YG occupancy: 961742 K (1763584 K)]
预清理阶段后，如果Eden 空间占用大于 CMSScheduleRemarkEdenSizeThreshold 设置的值, 会启动可中止预清理，直到占用率达到 CMSScheduleRemarkEdenPenetration 设置的值, 否则，立即安排重新标记阶段
2018-04-09T09:09:00.503+0800: 4902225.756: [Rescan (parallel) , 0.0234805 secs]
2018-04-09T09:09:00.527+0800: 4902225.780: [weak refs processing, 0.5607787 secs]
2018-04-09T09:09:01.088+0800: 4902226.341: [class unloading, 0.0376463 secs]
2018-04-09T09:09:01.125+0800: 4902226.378: [scrub symbol table, 0.0116193 secs]
2018-04-09T09:09:01.137+0800: 4902226.390: [scrub string table, 0.0099381 secs][1 CMS-remark: 18211959K(24254912K)] 19173702K(26018496K), 0.8348815 secs] [Times: user=1.32 sys=0.01, real=0.84 secs]
2018-04-09T09:09:01.339+0800: 4902226.592: Total time for which application threads were stopped: 0.8394764 seconds, Stopping threads took: 0.0006237 seconds
2018-04-09T09:09:01.339+0800: 4902226.592: [CMS-concurrent-sweep-start]
开始并发清理阶段，在清理阶段，应用线程还在运行。
2018-04-09T09:09:02.142+0800: 4902227.395: [GC (Allocation Failure) 2018-04-09T09:09:02.142+0800: 4902227.395: [ParNew
2018-04-09T09:09:02.213+0800: 4902227.467: Total time for which application threads were stopped: 0.0758979 seconds, Stopping threads took: 0.0004929 seconds
2018-04-09T09:09:04.510+0800: 4902229.763: [GC (Allocation Failure) 2018-04-09T09:09:04.510+0800: 4902229.763: [ParNew
2018-04-09T09:09:04.536+0800: 4902229.789: Total time for which application threads were stopped: 0.0298936 seconds, Stopping threads took: 0.0003532 seconds
2018-04-09T09:09:09.072+0800: 4902234.325: [GC (Allocation Failure) 2018-04-09T09:09:09.072+0800: 4902234.325: [ParNew
2018-04-09T09:09:09.098+0800: 4902234.352: Total time for which application threads were stopped: 0.0305002 seconds, Stopping threads took: 0.0005442 seconds
2018-04-09T09:09:12.345+0800: 4902237.599: [GC (Allocation Failure) 2018-04-09T09:09:12.346+0800: 4902237.599: [ParNew
2018-04-09T09:09:12.372+0800: 4902237.625: Total time for which application threads were stopped: 0.0303997 seconds, Stopping threads took: 0.0005283 seconds
2018-04-09T09:09:12.745+0800: 4902237.998: [CMS-concurrent-sweep: 11.239/11.406 secs] [Times: user=36.94 sys=0.67, real=11.40 secs] 并发清理阶段费时11.239秒
2018-04-09T09:09:12.745+0800: 4902237.998: [CMS-concurrent-reset-start]开始并发重置
2018-04-09T09:09:12.782+0800: 4902238.035: [CMS-concurrent-reset: 0.037/0.037 secs] [Times: user=0.19 sys=0.00, real=0.04 secs] 在本阶段，重新初始化CMS内部数据结构，以备下一轮 GC 使用。本阶段费时0.037秒
2018-04-09T09:09:16.382+0800: 4902241.635: [GC (Allocation Failure) 2018-04-09T09:09:16.382+0800: 4902241.635: [ParNew

Java GC日志可以通过 +PrintGCDetails开启
以ParallelGC为例
YoungGC日志解析

FullGC日志解析

当需要对大量的gc日志做整体的对比分析，可以使用工具例如http://www.gceasy.io/