目录

一.背景

二.CMS垃圾收集器特性

三.CMS执行步骤

四.CMS日志解释(JDK1.8)：

五.CMS参数&实践

六.实践触发CMS

七.CMS详细处理流程

八.优化建议

九.总结

一.背景

虽然现在有G1和jdk11的ZGC，但是还有很多企业都依然使用相对成熟的CMS，所以学习CMS还有有必要的。后面章节会分别说明G1和ZGC。

二.CMS垃圾收集器特性

三.CMS执行步骤

四.CMS日志解释(JDK1.8)：

1.代码展示：list占用引用，无法回收最终引发CMS GC。

2.JVM参数：

-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/tmp/gctest.log

3.GC日志

下面是一次完整的CMS GC的日志。

2018-10-30T16:03:58.382-0800: 147.320: [GC (CMS Initial Mark) [1 CMS-initial-mark: 147826K(273088K)] 167598K(351744K), 0.0066676 secs] [Times: user=0.04 sys=0.00, real=0.00 secs]

2018-10-30T16:03:58.389-0800: 147.327: [CMS-concurrent-mark-start]

2018-10-30T16:03:58.856-0800: 147.795: [CMS-concurrent-mark: 0.468/0.468 secs] [Times: user=0.86 sys=0.03, real=0.47 secs]

2018-10-30T16:03:58.856-0800: 147.795: [CMS-concurrent-preclean-start]

2018-10-30T16:03:58.857-0800: 147.795: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

2018-10-30T16:03:58.857-0800: 147.795: [CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time 2018-10-30T16:04:03.990-0800: 152.928: [CMS-concurrent-abortable-preclean: 2.533/5.133 secs] [Times: user=2.41 sys=0.05, real=5.14 secs]

2018-10-30T16:04:03.990-0800: 152.928: [GC (CMS Final Remark) [YG occupancy: 19771 K (78656 K)]2018-10-30T16:04:03.990-0800: 152.929: [Rescan (parallel) , 0.0090156 secs]2018-10-30T16:04:03.999-0800: 152.938: [weak refs processing, 0.0000437 secs]2018-10-30T16:04:03.999-0800: 152.938: [class unloading, 0.0003128 secs]2018-10-30T16:04:04.000-0800: 152.938: [scrub symbol table, 0.0006426 secs]2018-10-30T16:04:04.000-0800: 152.939: [scrub string table, 0.0002530 secs][1 CMS-remark: 147826K(273088K)] 167598K(351744K), 0.0105605 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

2018-10-30T16:04:04.001-0800: 152.939: [CMS-concurrent-sweep-start]

2018-10-30T16:04:04.106-0800: 153.044: [CMS-concurrent-sweep: 0.105/0.105 secs] [Times: user=0.09 sys=0.00, real=0.10 secs]

2018-10-30T16:04:04.106-0800: 153.044: [CMS-concurrent-reset-start]

2018-10-30T16:04:04.110-0800: 153.048: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

解释：

1. [GC (CMS Initial Mark) [1 CMS-initial-mark: 147826K(273088K)] 167598K(351744K), 0.0066676 secs] [Times: user=0.04 sys=0.00, real=0.00 secs]

   执行CMS-initial-mark(初始标记) old区使用=147826K(old区总大小=273088K)时触发了标记，  整个堆使用=167598K(整个堆空间大小=351744K) ，这个阶段花费了 0.0066676 secs。其中用户态cpu占用user=0.04秒，内核态cpu占用sys=0，真正物理耗时墙钟时间(也包含线程让出CPU给其他线程执行的时间)real=0.00秒，这里只保留两位，前面0.0066676 secs是该值的精确值，STW=0.0066676 secs。

  ps：CMS初始化标记阶段(需要stop the world),这个阶段标记的是由根(root)可直达的对象(也就是root之下第一层对象)，标记期间整个应用线程会停止。

2. [CMS-concurrent-mark: 0.468/0.468 secs] [Times: user=0.86 sys=0.03, real=0.47 secs]

 执行CMS-concurrent-mark(并发标记)     0.468/0.468 secs分别是占用CPU的时间和墙钟时间(此处解释参考http://ifeve.com/jvm-cms-log/)，此处应用正常运行，STW=0。

ps：开始并发标记阶段，之前被停止的应用线程会重新启动；从初始化阶段标记的所有可达的对象(root之下第一层队形)出发标记处第一层对象所引用的对象(root之下第二层、三层等等)。

3.[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

   并发预清理阶段花费0.001秒cpu时间和0.001秒时钟时间,此处应用正常运行，STW=0。

ps：预清理也属于并发处理阶段。这个阶段主要并发查找在做并发标记阶段时从年轻代晋升到老年代的对象或老年代新分配的对象(大对象直接进入老年代)或发生变化的线程(mutators)更新的对象，来减少重新标记阶段的工作量

4. CMS: abort preclean due to time 2018-10-30T16:04:03.990-0800: 152.928: [CMS-concurrent-abortable-preclean: 2.533/5.133 secs] [Times: user=2.41 sys=0.05, real=5.14 secs]

   可终止的并发预清理。总共花费2.533秒cpu时间和5.133秒时钟时间。此处应用正常运行，STW=0。

   ps:执行一些预清理，以减少remark阶段造成应用暂停的时间。

5.2018-10-30T16:04:03.990-0800: 152.928: [GC (CMS Final Remark) [YG occupancy: 19771 K (78656 K)]2018-10-30T16:04:03.990-0800: 152.929: [Rescan (parallel) , 0.0090156 secs]2018-10-30T16:04:03.999-0800: 152.938: [weak refs processing, 0.0000437 secs]2018-10-30T16:04:03.999-0800: 152.938: [class unloading, 0.0003128 secs]2018-10-30T16:04:04.000-0800: 152.938: [scrub symbol table, 0.0006426 secs]2018-10-30T16:04:04.000-0800: 152.939: [scrub string table, 0.0002530 secs][1 CMS-remark: 147826K(273088K)] 167598K(351744K), 0.0105605 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

重新标记阶段，会发生stop the world。最后标记老年代所有存活对象(包括在并发阶段创建或修改的对象)，因为之前的并发标记和并发预清理阶段都是和应用线程并发进行的，所以可能有遗漏对象，这个阶段会保证标记到所有对象。STW=0.0105605 secs

[YG occupancy: 19771 K (78656 K)]：当前使用了19771 K,年轻代大小为78656K,

[Rescan (parallel) , 0.0090156 secs]：在应用暂停后重新并发标记所有存活对象，总共耗时0.0090156秒

[weak refs processing, 0.0000437 secs]：子阶段1---处理弱引用，共耗时0.0000437秒

[class unloading, 0.0003128 secs]：子阶段2---卸载已不使用的类，共耗时0.0003128秒

[scrub symbol table, 0.0006426 secs]：子阶段3--清理symbol table，共耗时0.0006426秒

[scrub string table, 0.0002530 secs]：子阶段4---清理string table，共耗时0.0002530秒

[1 CMS-remark: 147826K(273088K)] 167598K(351744K), 0.0105605 secs]：重新标记，老年代占用147826K，总容量273088K；整个堆占用167598K，总容量351744K。共耗时0.0105605秒

6.CMS-concurrent-sweep: 0.105/0.105 secs] [Times: user=0.09 sys=0.00, real=0.10 secs

并发清理总共耗时 0.105秒cpu时间和 0.105秒时钟时间,STW=0。

ps:开始并发清理所有未标记或已终结的对象

7.CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs

  并发重置总共耗时 0.004秒cpu时间 0.004秒时钟时间,STW=0。

 ps:开始并发重置CMS算法内部数据，为下次垃圾回收做准备。

此次CMS 总STW=0.0066676 secs+0.017 secs=0.0172281secs

五.CMS参数&实践

参数实践

-XX:-+DisableExplicitGC

图1：未配置次参数，调用 System.gc();

图2.gc日志，可以看出发生一次system.gc的fullgc

图3.配置参数-XX:-+DisableExplicitGC

图4.gc日志，可以看出未发生fullfc

2.参数XX:+ExplicitGCInvokesConcurrent

可以看出发生了正常的CMS GC，而不是fullGC

3.参数-XX:+CMSClassUnloadingEnabled，默认开启

4.-XX:+PrintFlagsFinal 功能同jinfo

控制输出所有参数，可查默认值。

由于篇幅太长不在这里一一列举了。。。

六.实践触发CMS

模拟内存不足

新生代内存不足和新生代晋升老年代老年代不足分别报错

七.CMS详细处理流程

1>.初始标记

标记老年代中所有的GC Roots对象

标记年轻代中活着的对象引用到的老年代的对象（指的是年轻带中还存活的引用类型对象，引用指向老年代中的对象）

可作为GC Roots对象的包括如下几种：

1. 虚拟机栈(栈桢中的本地变量表)中的引用的对象 ；

2. 类静态属性引用的对象 ；

3. 常量池引用的对象 ；

4. 本地方法栈中JNI的引用的对象；

2>.并发标记

因为是并发运行的，在运行期间会发生新生代的对象晋升到老年代、或者是直接在老年代分配对象、或者更新老年代对象的引用关系等等，对于这些对象，都是需要进行重新标记的，否则有些对象就会被遗漏，发生漏标的情况。为了提高重新标记的效率，该阶段会把上述对象所在的Card标识为Dirty，后续只需扫描这些Dirty Card的对象，避免扫描整个老年代；

3>.预清理阶段

前一个阶段已经说明，不能标记出老年代全部的存活对象，是因为标记的同时应用程序会改变一些对象引用，这个阶段就是用来处理前一个阶段因为引用关系改变导致没有标记到的存活对象的，它会扫描所有标记为Direty的Card

如下图所示，在并发清理阶段，节点3的引用指向了6；则会把节点3的card标记为Dirty；

最后将6标记为存活,如下图所示：

4>.可终止的预处理

这个阶段尝试着去承担下一个阶段Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。

ps:此阶段最大持续时间为5秒，之所以可以持续5秒，另外一个原因也是为了期待这5秒内能够发生一次ygc，清理年轻带的引用，是的下个阶段的重新标记阶段，扫描年轻带指向老年代的引用的时间减少；

5>.重新标记

这个阶段会导致第二次stop the word，该阶段的任务是完成标记整个年老代的所有的存活对象。

这个阶段，重新标记的内存范围是整个堆，包含_young_gen和_old_gen。为什么要扫描新生代呢，因为对于老年代中的对象，如果被新生代中的对象引用，那么就会被视为存活对象，即使新生代的对象已经不可达了，也会使用这些不可达的对象当做cms的“gc root”，来扫描老年代； 因此对于老年代来说，引用了老年代中对象的新生代的对象，也会被老年代视作“GC ROOTS”:当此阶段耗时较长的时候，可以加入参数-XX:+CMSScavengeBeforeRemark，在重新标记之前，先执行一次ygc，回收掉年轻带的对象无用的对象，并将对象放入幸存带或晋升到老年代，这样再进行年轻带扫描时，只需要扫描幸存区的对象即可，一般幸存带非常小，这大大减少了扫描时间

由于之前的预处理阶段是与用户线程并发执行的，这时候可能年轻带的对象对老年代的引用已经发生了很多改变，这个时候，remark阶段要花很多时间处理这些改变，会导致很长stop the word，所以通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候。

另外，还可以开启并行收集：-XX:+CMSParallelRemarkEnabled

6>.并发清理

通过以上5个阶段的标记，老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

这个阶段主要是清除那些没有标记的对象并且回收空间；

由于CMS并发清理阶段用户线程还在运行着，伴随程序运行自然就还会有新的垃圾不断产生，这一部分垃圾出现在标记过程之后，CMS无法在当次收集中处理掉它们，只好留待下一次GC时再清理掉。这一部分垃圾就称为“浮动垃圾”。

7>.并发重置

这个阶段并发执行，重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用

八.优化建议

  1>.一般CMS的GC耗时 80%都在remark阶段，如果发现remark阶段停顿时间很长，可以尝试添加该参数：-XX:+CMSScavengeBeforeRemark

  2>.CMS是基于标记-清除算法的，只会将标记为为存活的对象删除，并不会移动对象整理内存空间，会造成内存碎片，这时候我们需要用到这个参数;-XX:CMSFullGCsBeforeCompaction=n

CMS GC要决定是否在full GC时做压缩，会依赖几个条件。其中，

1. UseCMSCompactAtFullCollection 与 CMSFullGCsBeforeCompaction 是搭配使用的；前者目前默认就是true了，也就是关键在后者上。

2. 用户调用了System.gc()，而且DisableExplicitGC没有开启。

3. young gen报告接下来如果做增量收集会失败；简单来说也就是young gen预计old gen没有足够空间来容纳下次young GC晋升的对象。

上述三种条件的任意一种成立都会让CMS决定这次做full GC时要做压缩。

3>.执行CMS GC的过程中，同时业务线程也在运行，当年轻带空间满了，执行ygc时，需要将存活的对象放入到老年代，而此时老年代空间不足，这时CMS还没有机会回收老年带产生的，或者在做Minor GC的时候，新生代救助空间放不下，需要放入老年代，而老年代也放不下而产生concurrent mode failure。

      要确定发生concurrent mode failure的原因是因为碎片造成的，还是Eden区有大对象直接晋升老年代造成的，一般有大量的对象晋升老年代容易导致这个错，这种是存在优化空间的，要保证大部分对象尽肯能的再新生代gc掉。。

4>.在进行Minor GC时，Survivor Space放不下，对象只能放入老年代，而此时老年代也放不下造成的，多数是由于老年带有足够的空闲空间，但是由于碎片较多，新生代要转移到老年带的对象比较大,找不到一段连续区域存放这个对象导致的promotion failed

过早提升与提升失败

在 Minor GC 过程中，Survivor Unused 可能不足以容纳 Eden 和另一个 Survivor 中的存活对象， 那么多余的将被移到老年代， 称为过早提升（Premature Promotion）,这会导致老年代中短期存活对象的增长， 可能会引发严重的性能问题。 再进一步， 如果老年代满了， Minor GC 后会进行 Full GC， 这将导致遍历整个堆， 称为提升失败（Promotion Failure）。

早提升的原因

1. Survivor空间太小，容纳不下全部的运行时短生命周期的对象，如果是这个原因，可以尝试将Survivor调大，否则端生命周期的对象提升过快，导致老年代很快就被占满，从而引起频繁的full gc；

2. 对象太大，Survivor和Eden没有足够大的空间来存放这些大象；

提升失败原因

当提升的时候，发现老年代也没有足够的连续空间来容纳该对象。

为什么是没有足够的连续空间而不是空闲空间呢？

老年代容纳不下提升的对象有两种情况：

1. 老年代空闲空间不够用了；

2. 老年代虽然空闲空间很多，但是碎片太多，没有连续的空闲空间存放该对象；

解决方法

1. 如果是因为内存碎片导致的大对象提升失败，cms需要进行空间整理压缩；

2. 如果是因为提升过快导致的，说明Survivor 空闲空间不足，那么可以尝试调大 Survivor；

3. 如果是因为老年代空间不够导致的，尝试将CMS触发的阈值调低；

5>.导致回收停顿时间变长原因

linux使用了swap，内存换入换出（vmstat），尤其是开启了大内存页的时候，因为swap只支持4k的内存页，大内存页的大小为2M，大内存页在swap的交换的时候需要先将swap中4k内存页合并成一个大内存页再放入内存或将大内存页切分为4k的内存页放入swap，合并和切分的操作会导致操作系统占用cup飙高，用户cpu占用反而很低；

除了swap交换外，网络io（netstat）、磁盘I/O （iostat）在 GC 过程中发生会使 GC 时间变长。

如果是以上原因，就要去查看gc日志中的Times耗时：

[Times: user=0.00 sys=0.00, real=0.00 secs]

user是用户线程占用的时间，sys是系统线程占用的时间，如果是io导致的问题，会有两种情况

1. user与sys时间都非常小，但是real却很长，如下：

[ Times: user=0.51 sys=0.10, real=5.00 secs ]

user+sys的时间远远小于real的值，这种情况说明停顿的时间并不是消耗在cup执行上了，不是cup肯定就是io导致的了，所以这时候要去检查系统的io情况。

sys时间很长，user时间很短，real几乎等于sys的时间，如下：

[ Times: user=0.11 sys=31.10, real=33.12 secs ]

这时候其中一种原因是开启了大内存页，还开启了swap，大内存进行swap交换时会有这种现象；

6>.增加线程数

CMS默认启动的回收线程数目是 (ParallelGCThreads + 3)/4) ，这里的ParallelGCThreads是年轻代的并行收集线程数，感觉有点怪怪的；

年轻代的并行收集线程数默认是(ncpus <= 8) ? ncpus : 3 + ((ncpus * 5) / 8)，可以通过-XX:ParallelGCThreads= N 来调整；

如果要直接设定CMS回收线程数，可以通过-XX:ParallelCMSThreads=n，注意这个n不能超过cpu线程数，需要注意的是增加gc线程数，就会和应用争抢资源

九.总结

CMS并发GC不是“full GC”。HotSpot VM里对concurrent collection和full collection有明确的区分。所有带有“FullCollection”字样的VM参数都是跟真正的full GC相关，而跟CMS并发GC无关的，cms收集算法只是清理老年代。