一篇文章教你弄懂java CMS垃圾回收日志

写在前面： 我是「境里婆娑」。我还是从前那个少年，没有一丝丝改变，时间只不过是考验，种在心中信念丝毫未减，眼前这个少年，还是最初那张脸，面前再多艰险不退却。
写博客的目的就是分享给大家一起学习交流，如果您对 Java感兴趣，可以关注我，我们一起学习。

本篇文章主要介绍程序出现Full Gc问题时，如何查看GC日志，帮助我们快速定位问题。以及使用工具定位FGC。

一、CMS垃圾回收器介绍

• CMS只会回收老年代和永久带（1.8开始为元数据区，需要设置CMSClassUnloadingEnabled），不会收集年轻带；
• CMS是一种预处理垃圾回收器，它不能等到old内存用尽时回收，需要在内存用尽前，完成回收操作，否则会导致并发回收失败；所以cms垃圾回收器开始执行回收操作，有一个触发阈值，默认是老年代或永久带达到92%。

CMS 特点

  针对老年代；
  基于"标记-清除"算法(不进行压缩操作，产生内存碎片)；            
  以获取最短回收停顿时间为目标；
  并发收集、低停顿；
  需要更多的内存（看后面的缺点）； 
  是HotSpot在JDK1.5推出的第一款真正意义上的并发（Concurrent）收集器；
  一次实现了让垃圾收集线程与用户线程（基本上）同时工作；

应用场景

  与用户交互较多的场景；        
  希望系统停顿时间最短，注重服务的响应速度；
  以给用户带来较好的体验；
  如常见WEB、B/S系统的服务器上的应用；

如果想要详细了其他垃圾回收器可以看这篇文章：Java虚拟机垃圾回收(三) 7种垃圾收集器

因为本文不涉及详细介绍CMS垃圾回收器特点，如果想了解可以查看Java官方文章：Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide

二、CMS JVM运行参数

如果你要在生产环境中使用CMS GC，下面这些跟日志相关的参数是必备的，有了这些参数，你才能排查基本的垃圾回收问题。

-XX:+PrintCommandLineFlags	打印出启动参数行
-XX:+UseConcMarkSweepGC	参数指定使用CMS垃圾回收器
-XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=80	参数指定CMS垃圾回收器在老年代达到80%的时候开始工作，如果不指定那么默认的值为92%
-XX:+CMSClassUnloadingEnabled	开启永久带（jdk1.8以下版本）或元数据区（jdk1.8及其以上版本）收集，如果没有设置这个标志，一旦永久代或元数据区耗尽空间也会尝试进行垃圾回收，但是收集不会是并行的，而再一次进行Full GC；
-XX:+UseParNewGC	使用cms时默认这个参数就是打开的，不需要配置，cms只回收老年代，年轻带只能配合Parallel New或Serial回收器
-XX:+CMSParallelRemarkEnabled	减少Remark阶段暂停的时间，启用并行Remark，如果Remark阶段暂停时间长，可以启用这个参数
-XX:+CMSScavengeBeforeRemark	如果Remark阶段暂停时间太长，可以启用这个参数，在Remark执行之前，先做一次ygc。因为这个阶段，年轻带也是cms的gcroot，cms会扫描年轻带指向老年代对象的引用，如果年轻带有大量引用需要被扫描，会让Remark阶段耗时增加；
-XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0	两个参数是针对cms垃圾回收器碎片做优化的，CMS是不会移动内存的， 运行时间长了，会产生很多内存碎片， 导致没有一段连续区域可以存放大对象，出现”promotion failed”、”concurrent mode failure”, 导致fullgc，启用UseCMSCompactAtFullCollection 在FULL GC的时候， 对年老代的内存进行压缩。-XX:CMSFullGCsBeforeCompaction=0 则是代表多少次FGC后对老年代做压缩操作，默认值为0，代表每次都压缩, 把对象移动到内存的最左边，可能会影响性能,但是可以消除碎片；
-XX:ConcGCThreads=4	定义并发CMS过程运行时的线程数。比如value=4意味着CMS周期的所有阶段都以4个线程来执行。尽管更多的线程会加快并发CMS过程，但其也会带来额外的同步开销。因此，对于特定的应用程序，应该通过测试来判断增加CMS线程数是否真的能够带来性能的提升。如果未设置这个参数，JVM会根据并行收集器中的-XX:ParallelGCThreads参数的值来计算出默认的并行CMS线程数：ParallelGCThreads = (ncpus <=8 ? ncpus : 8+(ncpus-8)*5/8) ，ncpus为cpu个数，ConcGCThreads =(ParallelGCThreads + 3)/4这个参数一般不要自己设置，使用默认就好，除非发现默认的参数有调整的必要；
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+ExplicitGCInvokesConcurrent	开启foreground CMS GC，CMS gc 有两种模式，background和foreground，正常的cms gc使用background模式，就是我们平时说的cms gc；当并发收集失败或者调用了System.gc()的时候，就会导致一次full gc，这个fullgc是不是cms回收，而是Serial单线程回收器，加入了参数后，执行full gc的时候，就变成了CMS foreground gc，它是并行full gc，只会执行cms中stop the world阶段的操作，效率比单线程Serial full GC要高；需要注意的是它只会回收old，因为cms收集器是老年代收集器；而正常的Serial收集是包含整个堆的，加入了参数,代表永久带也会被cms收集；
-XX:+PrintGCDetails -XX:+PrintGCCause -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:…/logs/gc.log	是打印gc日志，其中 -XX:+PrintGCCause 在jdk1.8之后无需设置
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=…/dump	是内存溢出时dump堆

三、CMS收集器运行过程

CMS收集器大致分为四个过程：初始标记（CMS initial mark）、并发标记（CMS concurrent mark）、重新标记（CMS remark）并发清除（CMS concurrent sweep）

1、初始标记（CMS initial mark）

仅标记一下GC Roots能直接关联到的对象；速度很快；但需要"Stop The World"；初始标记详细日志。

2020-05-17T14:58:08.997+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 22630K(125696K)] 22743K(126848K), 0.0011803 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

GC日志详细解析：
CMS初始化标记阶段(需要stop the world),这个阶段标记的是由根(root)可直达的对象(也就是root之下第一层对象)，标记期间整个应用线程会停止。老年代容量为125696K，在使用了22630K时触发了该标记操作；整个堆容量为126848K，在使用了22743K时触发了改标记，共耗时0.0011803 秒

这是CMS中两次stop-the-world事件中的一次。这一步的作用是标记存活的对象，有两部分：

1. 标记老年代中所有的GC Roots对象，如下图节点1；
2. 标记年轻代中活着的对象引用到的老年代的对象（指的是年轻带中还存活的引用类型对象，引用指向老年代中的对象）如下图节点2、3；
   
   **补充知识点：**在Java语言里，可作为GC Roots对象的包括以下四种：
3. 方法区中的常量引用的对象 ；
4. 本地方法栈中JNI的引用的对象；
5. 方法区中的类静态属性引用的对象 ；
6. 虚拟机栈(栈桢中的本地变量表)中的引用的对象 ；
   ps：为了加快此阶段处理速度，减少停顿时间，可以开启初始标记并行化，-XX:+CMSParallelInitialMarkEnabled，同时调大并行标记的线程数，线程数不要超过cpu的核数；

2、并发标记（CMS concurrent mark）

进行GC Roots Tracing的过程；刚才产生的集合中标记出存活对象；应用程序也在运行；并不能保证可以标记出所有的存活对象；详细GC日志如下。

2020-05-17T14:58:08.998+0800: [CMS-concurrent-mark-start]
2020-05-17T14:58:09.044+0800: [CMS-concurrent-mark: 0.047/0.047 secs] [Times: user=0.08 sys=0.00, real=0.05 secs] 

并发标记总共花费0.047秒cpu时间和0.047秒时钟时间(人可感知的时间)

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

并发标记总结：
从“初始标记”阶段标记的对象开始找出所有存活的对象;
因为是并发运行的，在运行期间会发生新生代的对象晋升到老年代、或者是直接在老年代分配对象、或者更新老年代对象的引用关系等等，对于这些对象，都是需要进行重新标记的，否则有些对象就会被遗漏，发生漏标的情况。为了提高重新标记的效率，该阶段会把上述对象所在的Card标识为Dirty，后续只需扫描这些Dirty Card的对象，避免扫描整个老年代；
并发标记阶段只负责将引用发生改变的Card标记为Dirty状态，不负责处理；

这个阶段因为是并发的容易导致concurrent mode failure

3、重新标记（CMS remark）

为了修正并发标记期间因用户程序继续运作而导致标记变动的那一部分对象的标记记录； 需要"Stop The World"，且停顿时间比初始标记稍长，但远比并发标记短； 采用多线程并行执行来提升效率；详细日志：

2020-05-17T14:58:09.052+0800: [GC (CMS Final Remark) [YG occupancy: 1048 K (1152 K)][Rescan (parallel) , 0.0010037 secs][weak refs processing, 0.0007176 secs][class unloading, 0.0112964 secs][scrub symbol table, 0.0069825 secs][scrub string table, 0.0009315 secs][1 CMS-remark: 22630K(125696K)] 23678K(126848K), 0.0226336 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 

GC日志详解：
[YG occupancy:1048 K (1152 K)]：年轻代大小为1152 :,当前使用了1048 K

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

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

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

[scrub symbol table, 0.0069825 secs]：子阶段3–清理symbol table

[scrub string table, 0.0008130 secs]：子阶段4—清理string table

[1 CMS-remark: 22630K(125696K)] 23678K(126848K), 0.0226336 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] ：重新标记，老年代占用23678K，总容量126848K；整个堆占用23678K，总容量126848K。共耗时0.0226336 秒

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

4、并发清除（CMS concurrent sweep）

回收所有的垃圾对象；详细垃圾回收日志：

1 2020-05-17T14:58:09.094+0800: [CMS-concurrent-sweep: 0.013/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2 2020-05-17T14:58:09.095+0800: [CMS-concurrent-reset-start]
3 2020-05-17T14:58:09.098+0800: [CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

日志详解：
1、并发清理总共耗时0.013秒cpu时间和0.015 秒时钟时间
2、开始并发重置CMS算法内部数据，来未下次垃圾回收做准备
3、并发重置总共耗时0.003秒cpu时间/0.003秒时钟时间

标记为存活,如下图所示：

四、什么样原因会导致FGC

不管YGC还是FGC，都会造成一定程度的程序卡顿（即Stop The World问题：GC线程开始工作，其他工作线程被挂起），即使采用ParNew、CMS或者G1这些更先进的垃圾回收算法，也只是在减少卡顿时间，而并不能完全消除卡顿。

• 大对象：系统一次性加载了过多数据到内存中（比如SQL查询未做分页），导致大对象进入了老年代。
• 内存泄漏：频繁创建了大量对象，但是无法被回收（比如IO对象使用完后未调用close方法释放资源），先引发FGC，最后导致OOM.
• 程序频繁生成一些长生命周期的对象，当这些对象的存活年龄超过分代年龄时便会进入老年代，最后引发FGC.
• 程序BUG导致动态生成了很多新类，使得 Metaspace 不断被占用，先引发FGC，最后导致OOM.
• 代码中显式调用了gc方法，包括自己的代码甚至框架中的代码。
• JVM参数设置问题：包括总内存大小、新生代和老年代的大小、Eden区和S区的大小、元空间大小、垃圾回收算法等等

排查FGC问题常用工具

JDK的自带工具，包括jmap、jstat等常用命令：

• 查看堆内存各区域的使用率以及GC情况
  jstat -gcutil -h20 pid 1000
• 查看堆内存中的存活对象，并按空间排序
  jmap -histo pid | head -n20
• dump堆内存文件
  jmap -dump:format=b,file=heap pid
• 可视化的堆内存分析工具：JVisualVM、MAT等

本篇文章参考：GC Algorithms: Implementations
———————————————————————————————————
由于本人水平有限，难免有不足，恳请各位大佬不吝赐教！