JVM学习笔记（四）CMSGC⽇志详解
GC ⽇志参数
JVM的GC⽇志的主要参数包括如下⼏个：
-XX:+PrintGC 输出GC⽇志
消去反应的条件
-XX:+PrintGCDetails 输出GC的详细⽇志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以⽇期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进⾏GC的前后打印出堆的信息
远行的诗句-Xloggc:../logs/gc.log ⽇志⽂件的输出路径
垃圾收集器组合
下⾯列举典型的垃圾收集器组合 ParNew + CMS，讲解 GC ⽇志的含义。
下⾯先简单介绍这2个垃圾收集器：
ParNew : 年轻代垃圾收集器，多线程，采⽤标记—复制算法。
CMS：⽼年代的收集器，全称（Concurrent Mark and Sweep），是⼀种以获取最短回收停顿时间为⽬标的收集器。
⽇志详解
1. ParNew GC ⽇志
2017-05-01T14:20:34.306+0800: 44.642: [GC2017-05-01T14:20:34.306+0800: 44.642: [ParNew: 327680K->40960K(368640K), 0.0883899 cs] 327680K->60854K(1007616K), 0.0886153 cs] [Times: ur=0.56 sys=0.05, real=0.10 cs]
⽇志内容含义解释
2017-05-01T14:20:34.306+0800GC发⽣的时间
44.642GC开始，相对JVM启动的相对时间，单位是秒
GC区别MinorGC和FullGC的标识，这次代表的是MinorGC
ParNew收集器的名称
327680K->40960K收集前后年轻代的使⽤情况
(368640K)整个年轻代的容量
0.0883899 cs该区域 gc 所花的时间
327680K->60854K收集前后整个堆的使⽤情况
(1007616K)整个堆的容量
0.0886153 cs GC 总时间拒绝面试
[Times: ur=0.56 sys=0.05, real=0.10 cs]GC事件在不同维度的耗时
CMS ⽇志
以下是⼀段完整的 CMS GC ⽇志记录，下⾯会对每⼀个环节进⾏拆解并做详细说明：
2017-05-18T20:32:21.029+0800: 442.193: [GC [1 CMS-initial-mark: 349375K(638976K)] 393510K(1
007616K), 0.0424478cs] [Times: ur=0.03 sys=0.0 2017-05-18T20:32:21.060+0800: 442.236: [CMS-concurrent-mark-start]
2017-05-18T20:32:21.279+0800: 442.452: [CMS-concurrent-mark: 0.216/0.216 cs][Times: ur=1.00 sys=0.13, real=0.22 cs]
2017-05-18T20:32:21.279+0800: 442.453: [CMS-concurrent-preclean-start]
2017-05-18T20:32:21.294+0800: 442.456: [CMS-concurrent-preclean: 0.004/0.004 cs][Times: ur=0.03 sys=0.00, real=0.01 cs]
2017-05-18T20:32:21.294+0800: 442.456: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2017-05-18T20:32:26.429+0800: 447.591: [CMS-concurrent-abortable-preclean: 4.238/5.134 cs][Times: ur=5.38 sy 2017-05-18T20:32:26.429+0800: 447.591: [GC[YG occupancy: 77380 K (368640 K)]2017-05-18T20:32:26.429+0800: 447.591: [Rescan (parallel) , 0.0219 2017-05-18T20:32:26.501+0800: 447.663: [CMS-concurrent-sweep-start]
2017-05-18T20:32:26.757+0800: 447.919: [CMS-concurrent-sweep: 0.256/0.256 cs][Times: ur=0.25 sys=0.00, real=0.26 cs]
小学教师资格证2017-05-18T20:32:26.757+0800: 447.919: [CMS-concurrent-ret-start]
潍坊风筝2017-05-18T20:32:26.760+0800: 447.922: [CMS-concurrent-ret: 0.003/0.003 cs][Times: ur=0.00 sys=0.00, real=0.00 cs]
1. 2017-05-18T20:32:21.029+0800: 44
2.193: [GC [1 CMS-initial-mark: 349375K(638976K)] 393510K(1007616K),
0.0424478 cs] [Times: ur=0.03 sys=0.00, real=0.03 cs]
这阶段是CMS初始化标记的阶段，从垃圾回收的“根对象”开始，且只扫描直接与“根对象”直接关联的对象，并做标记，在此期
间，其他线程都会停⽌。这时候的⽼年代容量为 638976K， 在使⽤到 349375K 时开始初始化标记。耗时短。
2. 2017-05-18T20:32:21.060+0800: 442.236: [CMS-concurrent-mark-start]
并发标记阶段，与⽤户线程并发执⾏，过程耗时很长。⽬的：从GC Root 开始对堆中对象进⾏可达性分析，找出存活的对象。
3. 2017-05-18T20:32:21.279+0800: 442.452: [CMS-concurrent-mark: 0.216/0.216 cs] [Times: ur=1.00
sys=0.13, real=0.22 cs]
并发标记阶段花费了0.216s cpu 时间 和0.216s 系统时间（包括其他线程占⽤cpu导致标记线程挂起的时间）
4. 2017-05-18T20:32:21.279+0800: 442.453: [CMS-concurrent-preclean-start]
并发预清理阶段，也是与⽤户线程并发执⾏。虚拟机查找在执⾏并发标记阶段新进⼊⽼年代的对象(可能会有⼀些对象从新⽣代晋升到⽼年代， 或者有⼀些对象被分配到⽼年代)。通过重新扫描，减少下⼀个阶段”重新标记”的⼯作，因为下⼀个阶段会Stop The
World。
5. 2017-05-18T20:32:21.294+0800: 442.456: [CMS-concurrent-preclean: 0.004/0.004 cs] [Times: ur=0.03
sys=0.00, real=0.01 cs]
该阶段花费了花费了 0.004s cpu 时间 和 0.004s 系统时间
6. 2017-05-18T20:32:21.294+0800: 442.456: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2017-05-18T20:32:26.429+0800: 447.591: [CMS-concurrent-abortable-preclean:
4.238/
5.134 cs] [Times: ur=5.38 sys=0.78, real=5.13 cs]
并发可中⽌预清理阶段，运⾏在并⾏预清理和重新标记之间，直到获得所期望的eden空间占⽤率。增加这个阶段是为了避免在重新标记阶段后紧跟着发⽣⼀次垃圾清除。为了尽可能区分开垃圾清除和重新标记 ，我们尽量安排在两次垃圾清除之间运⾏重新标记阶段。
7. 2017-05-18T20:32:26.429+0800: 447.591: [GC[YG occupancy: 77380 K (368640 K)]2017-05-
18T20:32:26.429+0800: 447.591: [Rescan (parallel) , 0.0219897 cs]2017-05-18T20:32:26.452+0800: 447.613: [weak refs processing, 0.0002341 cs]2017-05-18T20:32:26.452+0800: 447.614: [class unloading, 0.0172195 cs]2017-05-18T20:32:26.469+0800: 447.631: [scrub symbol table, 0.0180261 cs]2017-05-
18T20:32:26.487+0800: 447.649: [scrub string table, 0.0025024 cs] [1 CMS-remark: 349375K(638976K)]
426755K(1007616K), 0.0718764 cs] [Times: ur=0.19 sys=0.00, real=0.07 cs]
重新标记阶段，会暂停所有⽤户线程。该阶段的任务是完成标记整个年⽼代的所有的存活对象。
详解：人生无奈的句子
(1) 2016-08-23T11:23:08.447-0200: 65.550 – 时间
(2) CMS Final Remark – 收集阶段，这个阶段会标记⽼年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引⽤对
象
(3) YG occupancy: 77380 K (368640 K) – 年轻代当前占⽤情况和容量
(4) [Rescan (parallel) , 0.0219897 cs] – 重新标记所花的时间
(5) weak refs processing, 0.0002341 cs] –处理弱引⽤所花的时间
(6) class unloading, 0.0172195 cs] – 卸载⽆⽤的class所花的时间
(7) scrub string table, 0.0180261 cs – 暂时不清楚什么意思，⽹上找到⼀段英⽂解释（that is cleaning up symbol and
string tables which hold class-level metadata and internalized string respectively）
(8) 349375K(638976K) – 在这个阶段之后⽼年代占有的内存⼤⼩和⽼年代的容量
(9) 426755K(1007616K) – 在这个阶段之后整个堆的内存⼤⼩和整个堆的容量
(10) 0.0718764 cs – 这个阶段的持续时间
8. 2017-05-18T20:32:26.501+0800: 447.663: [CMS-concurrent-sweep-start]
并发清理阶段开始，与⽤户线程并发执⾏。
9. 2017-05-18T20:32:26.757+0800: 447.919: [CMS-concurrent-sweep: 0.256/0.256 cs] [Times: ur=0.25
sys=0.00, real=0.26 cs]
并发清理阶段结束，所⽤的时间。
10. 2017-05-18T20:32:26.757+0800: 447.919: [CMS-concurrent-ret-start]
2017-05-18T20:32:26.760+0800: 447.922: [CMS-concurrent-ret: 0.003/0.003 cs] [Times: ur=0.00
sys=0.00, real=0.00 cs]
开始并发重置。在这个阶段，与CMS相关数据结构被重新初始化，这样下⼀个周期可以正常进⾏。
以上过程是⼀个正常的CMS GC循环周期，接下来再分析⼀些不正常的⽇志。⽇志在笔者本地未能复现，下⾯内容转⾃互联⽹。
龙眼上火197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 cs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 cs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 cs] 663850K->248977K(1048384K), 2.3733725 cs]
这显⽰，ParNew收集请求执⾏，但是没有成功。因为此时系统估计没有⽼⽣代中没有⾜够的空间去容纳这些对象（预测之后可能会出现⽼
⽣代的空余空间将会被系统占光），我们称这种情况为 “full promotion guarantee failure”
在这种情况下下，并发式的CMS被阻塞了，full GC执⾏了，GC算法进⼊了concurrent mode failure状态，调⽤⼀个rail Old GC(阻塞
了其他线程)来清理系统的Heap
⽇志显⽰，Full GC花费了2.3733725s，⽼⽣代空间由402978K降到了248977K
concurrent mode failure可以通过增⼤⽼⽣代的空间或者通过设置CMSInitiatingOccupancyFraction⼀个⼩的值使得CMS Collection
发⽣的更频繁（CMSInitiatingOccupancyFraction可以控制CMS执⾏的时间，假设设置为70，说明⽼⽣代在利⽤率为70%时发⽣
CMS），但是把这个值设置⼩也会导致CMS发⽣更加频繁。
某些情况下，promotion failures也会发⽣，即使是⽼⽣代有⾜够的空间。这个原因是”fragmentation”-⽼⽣代的可⽤空间不是连续的，⽽将新⽣代的对象移动到⽼⽣代需要连续的可⽤空间。⽽CMS是不会对内存进⾏压缩的算法，因此造成了这种问题。
解释为什么会产⽣ concurrent mode failure 的原因：
西方建筑
CMS并发处理阶段⽤户线程还在运⾏中，伴随着程序运⾏会有新的垃圾产⽣，CMS⽆法处理掉它们（没有标记），只能在下⼀次GC的时候处理。同样的，⽤户线程运⾏就需要分配新的内存空间，为此，CMS收集器并不会在⽼年代全部被填满以后在进⾏收集，会预留⼀部分空间提供并发收集时的程序运⾏使⽤。即使是这样，还是会存在CMS运⾏期间预留的内存⽆法满⾜程序需求，就会出现”Concurrent Mode Failure”失败，这是，虚拟机将会启动备案操作：临时启动Serial Old 收集器来重新进⾏⽼年代的垃圾收集，Serial Old收集器会Stop
the world，这样会导致停顿时间过长
