实例透彻分析CMS垃圾收集器执行过程

CMS收集器收集步骤:

在上一次【https://www.cnblogs.com/webor2006/p/11055468.html】中已经对CMS的垃圾收集器有了一定的理论上的了解,其中提到了CMS收集器完整的七个步骤,这一次则对每一个步骤进行一个详细了解,并会用程序来理解这七个步骤。

  • Phase1 :Initial Mark【初始标记】
    这个是CMS两次stop-the-world事件的其中一次,这个阶段的目标是:标记那些直接被GC root引用或被年轻代存活对象所引用的所有对象。用图来表示:
    上面有对象是直接被GC ROOTS所指用的,有些对象是被年轻代引用的,都会被标记出来。
  • Phase2 : Concurrent Mark 【并发标记】
    在这个阶段Garbage Collector会遍历老年代,然后标记所有存活的对象,它会根据上个阶段找到GC ROOTS遍历查找。并发标记阶段,它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记,因为在标记期间用户的程序可能会改变一些引用。如下图:
    在上面的图中,与阶段1的图进行对比,就会发现有一个对象的引用已经发生了变化,如标黑的那个对象。
  • Phase3 : Concurrent Preclean【并发预先清除】
    这也是一个并发阶段,与应用的线程并发运行,并不会stop应用的线程。在并发运行的过程中,一些对象的引用可能会发生变化,但是这种情况发生时,JVM会将包含这个对象的区域(Card)标记为Dirty,这也就是Card Marking。
    在pre-clean阶段,那些能够从Dirty对象到达的对象也会被标记,这个标记做完之后,dirty card标记就会被清除了。
    下面看下示意图:

    上图中标红的则为Dirty,而能够被它所直接到达的对象也会被标记,标记完了则dirty card标记被清除,如下:

  • Phase4 : Concurrent Abortable Preclean【并发可能失败的预先清除】
    这也是一个并发阶段,但是同样不会影响用户的应用线程,这个阶段是为了尽量承担STW(stop-the-world)中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素,由于这个阶段是在重复做很多相同的工作,直接满足一些条件(比如:重复迭代的次数、完成的工作量或者时钟时间等)
  • Phase5 : Final Remark【最终重新标记】
    这是第二个STW阶段,也是CMS中的最后一个,这个阶段的目标是标记老年代所有的存活对象,由于之前的阶段是并发执行的,GC线程可能跟不上应用程序的变化,为了完成标记老年代所有存活对象的目标,STW就非常有必要了。
    通常CMS的Final Remark阶段会在年代代尽可能干净的时候运行,目的是为了减少连续STW发生的可能性(年轻代存活对象过多的话,也会导致老年代涉及的存活对象会很多)。这个阶段会比前面的几个阶段更复杂一些。
  • 标记阶段完成
    经历过以上五个阶段之后,老年代所有存活的对象都被标记过了,现在可以通过清除算法去清理那些老年代不再使用的对象。可见其实CMS是将一个标记阶段细分成五个子阶段了。
  • Phase6 : Concurrent Sweep【并发清除】
    这里不需要STW,它是与用户的应用程序并发运行,这个阶段是:清除那些不再使用的对象,回收它们的占用空间为将来使用,如图:
  • Phase7 : Concurrent Reset【并发重置】
    这个阶段也是并发执行的,它会重设CMS内部的数据结构,为下次的GC做准备。

好,下面来对CMS进行一个总结:CMS通过将大量工作分散到并发处理阶段来减少STW时间,在这块做得非常优秀,但是CMS也有一些其它的问题,主要是如下问题:
1、CMS收集器无法处理浮动垃圾(Floating Garbage),可能出现“Concurrent Mode Failure”失败而导致另一次Full GC的产生,可能引发串行Full GC;

2、空间碎片,导致无法分配大对象,CMS收集器提供了一个-XX:+UseCMSCompactAtFullCollection开发参数(默认就是开启的),用于在CMS收集器顶不住要进行Full GC时开启内存碎片的合并整理过程,内存整理的过程是无法并发的,空间碎片问题没有了,但停顿时间不得不变长;

3、对于堆比较大的应用,GC的时间难以预估。

实践来感受CMS的七大步骤:

关于CMS的七大步骤我们已经理论话的对它进行了学习,但是!!!还是有些抽象,所以接下来会用程序来加深对步骤的理解,可以完完整整通过实验来看到所有的步骤,先新建一个测试类:

目前程序是平淡无奇的,接下来给JVM增加一些启动参数,如下:

好,整个实验需要的JVM参数都已经设定好了,接下来运行看一下输出:

/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/bin/java -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -Dfile.encoding=UTF-8 -classpath /Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_92.jdk/Contents/Home/lib/tools.jar:/Users/xiongwei/Documents/workspace/IntelliJSpace/jvm_lectue/out/production/classes:/Users/xiongwei/.gradle/caches/modules-2/files-2.1/mysql/mysql-connector-java/5.1.34/46deba4adbdb4967367b013cbc67b7f7373da60a/mysql-connector-java-5.1.34.jar:/Users/xiongwei/.gradle/caches/modules-2/files-2.1/cglib/cglib/3.2.0/bced5c83ed985c080a24dc5a42b0ca631556f413/cglib-3.2.0.jar:/Users/xiongwei/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm/5.0.3/dcc2193db20e19e1feca8b1240dbbc4e190824fa/asm-5.0.3.jar:/Users/xiongwei/.gradle/caches/modules-2/files-2.1/org.apache.ant/ant/1.9.4/6d473e8653d952045f550f4ef225a9591b79094a/ant-1.9.4.jar:/Users/xiongwei/.gradle/caches/modules-2/files-2.1/org.apache.ant/ant-launcher/1.9.4/334b62cb4be0432769679e8b94e83f8fd5ed395c/ant-launcher-1.9.4.jar com.jvm.gc.MyTest5
111111
[GC (Allocation Failure) [ParNew: 5119K->354K(9216K), 0.0038338 secs] 5119K->4452K(19456K), 0.0038874 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
222222
333333
[GC (Allocation Failure) [ParNew (promotion failed): 6657K->6814K(9216K), 0.0038483 secs][CMS: 8196K->8192K(10240K), 0.0041740 secs] 10755K->10573K(19456K), [Metaspace: 2650K->2650K(1056768K)], 0.0080758 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[GC (CMS Initial Mark) [1 CMS-initial-mark: 8192K(10240K)] 14669K(19456K), 0.0005176 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-preclean-start]
444444
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (CMS Final Remark) [YG occupancy: 6800 K (9216 K)][Rescan (parallel) , 0.0020690 secs][weak refs processing, 0.0000105 secs][class unloading, 0.0002582 secs][scrub symbol table, 0.0005401 secs][scrub string table, 0.0001471 secs][1 CMS-remark: 8192K(10240K)] 14992K(19456K), 0.0031107 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 6964K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  85% used [0x00000007bec00000, 0x00000007bf2cd1e0, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 concurrent mark-sweep generation total 10240K, used 8192K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2657K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 287K, capacity 386K, committed 512K, reserved 1048576K

Process finished with exit code 0

哇~~好神奇,输出了这么多日志,下面咱们来仔细分析一下:

下面具体来分析一下GC的日志:

这不就是七大阶段的第一阶段么?

接下来继续:

这不是对应七大步骤的第二步骤么?

接着第三个阶段:

对应第四个阶段:

接着对应第五个步骤了,执行了一次STW了:

其中这个阶段的日志信息有点多,下面解读一下:

接着继续:

对应第六个阶段:

最后一阶段:

整个CMS垃圾收集器处理完之后,接下来看一下堆的情况:

原文地址:https://www.cnblogs.com/webor2006/p/11110263.html