java CMS垃圾回收日志

文章目录
一、CMS垃圾回收器介绍
二、CMS JVM运行参数
三、CMS收集器运行过程
1、初始标记（CMS initial mark）
2、并发标记（CMS concurrent mark）
3、重新标记（CMS remark）
4、并发清除（CMS concurrent sweep）
四、什么样原因会导致FGC

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

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

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

应用场景

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

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

image.png

三、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事件中的一次。这一步的作用是标记存活的对象，有两部分：

标记老年代中所有的GC Roots对象，如下图节点1；
标记年轻代中活着的对象引用到的老年代的对象（指的是年轻带中还存活的引用类型对象，引用指向老年代中的对象）如下图节点2、3；

image.png

补充知识点：在Java语言里，可作为GC Roots对象的包括以下四种：
方法区中的常量引用的对象 ；
本地方法栈中JNI的引用的对象；
方法区中的类静态属性引用的对象 ；
虚拟机栈(栈桢中的本地变量表)中的引用的对象 ；
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状态，不负责处理；

image.png

这个阶段因为是并发的容易导致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

image.png

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秒时钟时间

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

image.png

四、什么样原因会导致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等

————————————————
版权声明：本文为CSDN博主「境里婆娑」的原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/TreeShu321/article/details/106173507