Java
Java虚拟机

Java虚拟机06 - 垃圾收集器之CMS

简介:Java虚拟机在执行Java程序的过程中会把它所管理的内存划分为若干个不同的数据区域。这些区域都有各自的用途,以及创建和销毁的时间,有的区域随着虚拟机进程的启动而存在,有些区域则依赖用户线程的启动和结束而建立和销毁。

1. CMS收集器简介

CMS(Concurrent Mark Sweep)收集器是一种以获取最短回收停顿时间为目标的收集器,也是基于“标记—清除”算法实现的,它的运作整个过程细分为6个步骤,包括:

  • 初始标记(CMS initial mark):需要“Stop The World”,标记一下GC Roots能直接关联到的对象,速度很快。
  • 并发标记(CMS concurrent mark):进行GC Roots Tracing的过程,根据初始标记阶段发现的所有GC Roots所关联的对象扫描整个老年代,标记所有存活对象。
  • 预清理(CMS pre clean):用于清理前准备和检查,并根据历史性能数据来决定控制停顿时间进行重新标记。
  • 重新标记(CMS remark):需要“Stop The World”,修正并发标记期间因用户程序继续运作而导致标记产生变动的那一部分对象的标记记录,这个阶段的停顿时间一般会比初始标记阶段稍长一些,但远比并发标记的时间短。
  • 并发清除(CMS concurrent sweep):清理垃圾。
  • 并发重置(CMS concurrent reset):垃圾回收完成后,重新初始化CMS数据和相应的数据结构。

1.1. CMS收集器缺点

CMS有以下3个明显的缺点:

  1. CMS收集器对CPU资源非常敏感。CMS默认启动的回收线程数是( CPU Count + 3 ) / 4,当CPU在4个以上时,并发回收时垃圾收集线程不少于25%的CPU资源,并且随着CPU数量的增加而下降。但是当CPU不足4个(譬如2个)时,将分出一半的运算能力去执行收集器线程,就可能导致用户程序的执行速度忽然降低了50%。

  2. CMS收集器无法处理浮动垃圾(Floating Garbage),可能出现“Concurrent Mode Failure”失败而导致另一次Full GC的产生。浮动垃圾是指CMS在并发清理阶段用户线程还在同时执行时产生的垃圾。由于在垃圾收集阶段用户线程还需要运行,还需要预留有足够的内存空间给用户线程使用,因此需要预留一部分空间提供并发收集时的程序运作使用。在JDK 1.5的默认设置下,CMS收集器当老年代使用了68%的空间后就会被激活,可以适当调高参数-XX:CMSInitiatingOccupancyFraction的值来提高触发百分比,以降低内存回收次数;在JDK 1.6中,CMS收集器的启动阈值已经提升至92%。如果运行期间预留的内存无法满足程序需要,就会出现一次“Concurrent Mode Failure”失败,这时虚拟机将临时启用Serial Old收集器来重新进行老年代的垃圾收集,导致停顿时间就很长了。所以说参数-XX:CMSInitiatingOccupancyFraction设置得太高很容易导致大量“Concurrent Mode Failure”失败,性能反而降低。

  3. CMS是一款基于“标记—清除”算法实现的收集器,收集结束时会有大量空间碎片产生。空间碎片过多无法找到足够大的连续空间来分配当前对象,不得不提前触发一次Full GC。为了解决这个问题,CMS收集器提供了一个-XX:+UseCMSCompactAtFullCollection开关参数(默认就是开启的),用于在CMS收集器要进行Full GC时开启内存碎片的合并整理过程,内存整理的过程是无法并发的,因此也会导致停顿时间变长。而另外一个参数-XX:CMSFullGCsBeforeCompaction可以设置执行多少次不压缩的Full GC后,才执行一次带压缩的(默认值为0,即每次进入Full GC时都进行碎片整理)。

CMS收集器过程示意图如下:

1.CMS运行流程.png

2. CMS日志分析

通过设置Tomcat的CATALINA_OPTS参数如下来获取CMS详细的GC日志:

  • CATALINA_OPTS="-Xloggc:/Users/qinly/Desktop/Java_Test/gc.log -XX:+PrintGCDetails -Xms128M -Xmx128M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/qinly/Desktop/Java_Test/ -XX:+UseConcMarkSweepGC -XX:PermSize=32M"

进行JMeter压测后,可以得到下面的GC日志信息(以一次CMS GC过程为主):

  • 8.596: [GC [1 CMS-initial-mark: 59940K(109824K)] 62192K(128960K), 0.0021269 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
  • 8.598: [CMS-concurrent-mark-start]
  • 8.684: [CMS-concurrent-mark: 0.073/0.086 secs] [Times: user=0.17 sys=0.02, real=0.09 secs]
  • 8.684: [CMS-concurrent-preclean-start]
  • 8.685: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
  • 8.685: [CMS-concurrent-abortable-preclean-start]
  • 9.039: [GC 9.039: [ParNew: 19136K->2112K(19136K), 0.0121800 secs] 79076K->69019K(128960K), 0.0122511 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
  • 9.303: [CMS-concurrent-abortable-preclean: 0.586/0.618 secs] [Times: user=1.16 sys=0.14, real=0.62 secs]
  • 9.303: [GC[YG occupancy: 15489 K (19136 K)]9.304: [Rescan (parallel) , 0.0025348 secs]9.306: [weak refs processing, 0.0000390 secs] [1 CMS-remark: 66907K(109824K)] 82396K(128960K), 0.0026284 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
  • 9.308: [CMS-concurrent-sweep-start]
  • 9.381: [GC 9.381: [ParNew: 19136K->2112K(19136K), 0.0116226 secs] 85293K->74845K(128960K), 0.0116999 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
  • 9.437: [CMS-concurrent-sweep: 0.099/0.129 secs] [Times: user=0.21 sys=0.04, real=0.13 secs]
  • 9.437: [CMS-concurrent-reset-start]
  • 9.438: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

接下来将针对上面的日志,一步步进行分析。

2.1 初始标记

在上面日志的第1行中,8.596秒进行了CMS的初始标记过程,这个阶段的目标是标记老年代所有的GC root可达对象、年轻代中被引用的对象:

  • 8.596: [GC [1 CMS-initial-mark: 59940K(109824K)] 62192K(128960K), 0.0021269 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

日志详细拆解如下:

  1. 8.596:即GC时间开始时间。
  2. [1 CMS-initial-mark: 59940K(109824K)] 62192K(128960K), 0.0021269 secs]:表明当前阶段为初始标记阶段,其中59940K(109824K)表示老年代当前已使用堆内存大小(老年代堆内存总大小)62192K(128960K)表示总堆内存已使用大小(总堆内存总大小)0.0021269 secs表示本次过程持续时间。
  3. [Times: user=0.00 sys=0.00, real=0.00 secs]:表示本次过程user、sys、real的实际时间。

注1:user、sys、real实际时间解释:
- user:用户态消耗的CPU时间;
- sys:内核态消耗的CPU时间;
- real:操作从开始到结束所经过的墙钟时间(Wall Clock Time)。

注2:CPU时间与墙钟时间的区别是,墙钟时间包括各种非运算的等待耗时,例如等待I/O、等待线程阻塞,而CPU时间不包括这些耗时;当系统有多CPU或者多核时,多线程操作会叠加这些CPU时间,所以user或sys时间超过real时间是正常的。

2.2 并发标记

在上面日志的第2 ~ 3行日志中,8.598 ~ 8.684秒进行了CMS的并发标记过程,这个阶段期间,垃圾收集器将根据初始标记阶段发现的所有GC Roots所关联的对象扫描整个老年代,标记所有存活对象。并发标记线程和应用线程并发运行,不会停顿应用线程。由于并发标记期间用户线程一直在运行,老年代某些非存活对象也可能会被标记:

  • 8.598: [CMS-concurrent-mark-start]
  • 8.684: [CMS-concurrent-mark: 0.073/0.086 secs] [Times: user=0.17 sys=0.02, real=0.09 secs]

日志详细拆解如下:

  1. [CMS-concurrent-mark-start]:表示并发标记开始。
  2. [CMS-concurrent-mark: 0.073/0.086 secs]:表示本次过程持续时间 / 墙钟时间。

2.3 预清理

在上面日志的第4 ~ 8行日志中,8.684 ~ 8.685秒进行了CMS的预清理记过程。预清理阶段是为了接下来的正式清理阶段做准备和检查。由于接下来的重新标记是需要“Stop the World”的,如果新生代GC发生后立即触发一次重新标记可能会导致停顿时间很长,为了避免这种情况,预处理阶段可能会等待一次新生代GC的发生,然后根据历史性能数据预测下一次新生代GC可能发生的时间,然后在当前时间和预测时间的中间时刻,进行重写标记,从最大程度避免新生代GC和重新标记的时间重合导致大量停顿时长。

  • 8.684: [CMS-concurrent-preclean-start]
  • 8.685: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
  • 8.685: [CMS-concurrent-abortable-preclean-start]
  • 9.039: [GC 9.039: [ParNew: 19136K->2112K(19136K), 0.0121800 secs] 79076K->69019K(128960K), 0.0122511 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
  • 9.303: [CMS-concurrent-abortable-preclean: 0.586/0.618 secs] [Times: user=1.16 sys=0.14, real=0.62 secs]

在上面的日志中可以看到,第3行CMS-concurrent-abortable-preclean-start执行之后,第4行等待了一次新生代的ParNew GC操作的进行(从8.685 ~ 9.039接近0.5s的等待时间),如下:

  • 9.039: [GC 9.039: [ParNew: 19136K->2112K(19136K), 0.0121800 secs] 79076K->69019K(128960K), 0.0122511 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

预清理阶段的日志详细拆解如下:

  1. [CMS-concurrent-preclean-start]:表示预清理过程开始。
  2. [CMS-concurrent-abortable-preclean-start]:启动可终止的预清理过程。
  3. [GC 9.039: [ParNew: 19136K->2112K(19136K), 0.0121800 secs] 79076K->69019K(128960K), 0.0122511 secs]:表示进行了一次ParNew GC操作,其中19136K->2112K(19136K)表示新生代堆内存GC前已使用大小 -> 新生代堆内存GC后已使用大小(新生代堆内存总大小)0.0121800 secs表示ParNew GC消耗时间;79076K->69019K(128960K)表示总堆内存GC前已使用大小 -> 总堆内存GC后已使用大小(总堆内存总大小)0.0122511 secs表示整个过程消耗时间。
  4. [CMS-concurrent-abortable-preclean: 0.586/0.618 secs]:表示本次预清理持续时间 / 墙钟时间( 9.303 - 8.685 = 0.618)。

2.4 重新标记

在上面的日志第9行记录中,9.303秒进行了一次重新标记过程。由于并发标记阶段是用户线程一起并发执行的,用户对象引用可能会发生进一步改变。重新标记阶段会再一次“Stop the World”以修正标记产生变动的那一部分对象的标记记录。重新标记的示意图如下:

2.CMS重新标记.png

重新标记过程的日志如下:

  • 9.303: [GC[YG occupancy: 15489 K (19136 K)]9.304: [Rescan (parallel) , 0.0025348 secs]9.306: [weak refs processing, 0.0000390 secs] [1 CMS-remark: 66907K(109824K)] 82396K(128960K), 0.0026284 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

日志详细拆解如下:

  1. [YG occupancy: 15489 K (19136 K)]:表示当前新生代的情况,15489 K (19136 K)表示新生代已使用堆内存大小(新生代总堆内存大小)
  2. [Rescan (parallel) , 0.0025348 secs]:Rescan阶段(CMS Remark阶段的一个子阶段),会扫描新生代和老年代中的对象,此阶段是并行进行的,花费0.0025348秒。
  3. [weak refs processing, 0.0000390 secs]:弱引用对象处理阶段,花费0.0000390秒。
  4. [1 CMS-remark: 66907K(109824K)] 82396K(128960K), 0.0026284 secs]:表示重新标记过程,66907K(109824K)表示老年代已使用堆内存大小(老年代总堆内存大小)82396K(128960K)表示总堆内存已使用大小(总堆内存总大小)
  5. 0.0026284 secs:表示本次重新标记持续时间为0.0026284秒。

注:重新标记有五个子阶段,上面只展示了Rescan和weak refs processing两个,还有三个阶段如下:
- class unloading:卸载无用的class对象;
- scrub symbol table:清除拥有class级别元数据的符号;
- scrub string table:清除拥有class级别元数据的字符串表和其内部的String。

2.5 并发清除

在上面的日志第10 ~ 12行记录中,9.308 ~ 9.437秒进行了一次并发清除过程。并发标记过程是与用户线程一起并发执行的,耗时会长一点。

  • 9.308: [CMS-concurrent-sweep-start]
  • 9.381: [GC 9.381: [ParNew: 19136K->2112K(19136K), 0.0116226 secs] 85293K->74845K(128960K), 0.0116999 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
  • 9.437: [CMS-concurrent-sweep: 0.099/0.129 secs] [Times: user=0.21 sys=0.04, real=0.13 secs]

日志详细拆解如下:

  1. [CMS-concurrent-sweep-start]:表示并发清除阶段开始。
  2. [GC 9.381: [ParNew: 19136K->2112K(19136K), 0.0116226 secs] 85293K->74845K(128960K), 0.0116999 secs]:由于Major GC操作一般伴随着一次Minor GC,这里表示新生代执行了ParNew GC操作。
  3. [CMS-concurrent-sweep: 0.099/0.129 secs]:表示本次并发清除持续时间 / 墙钟时间( 9.437 - 9.308 = 0.129)。

2.6 并发重置

在上面的日志第13 ~ 14行记录中,9.437 ~ 9.438秒进行了一次并发重置过程,日志如下:

  • 9.437: [CMS-concurrent-reset-start]
  • 9.438: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]