CMS之promotion failed&concurrent mode failure

背景

线上的服务使用zk临时节点进行保活,偶尔发现zk有超时现象(timeout=80s,心跳=5s)发生,开始怀疑网络,zk造成的,后来经过排查机器物理监控,网络,cpu,io都未发现异常,zk leader也没有发生切换,同时观察zk的指标监控未发现异常。所以把解决问题的思路放在了服务本身上。

经过查看日志,发现服务在超时的时间里未打印任何日志(包括心跳线程日志),这个现象我们定了几个排查方向:

  1. jvm gc(stw)
  2. io 阻塞:log4j打印日志

通过查看log4j原理,发现log4j是异步打印日志。系统也未发现网络,磁盘io异常,所以把重点放在了jvm gc上,临时做了一些监控和告警:

  1. 增加电话告警
  2. 调整启动参数,打印gc日志
    1. -XX:+PrintGCDetails -XX:+PrintGCDateStamps
    2. -Xloggc: 执行单独的gc日志
  3. 增加zk sessiontimeout(client+server都需要调整,实际使用的是两者的较小值)

LATER

虽然第二天没有发生zk超时问题,因为有gc log,所以我们还是分析了一下

通过工具(https://gceasy.io/gc-index.jsp)发现:

发现最大gc时间居然达到了45s

1
2
3
4
5
6
7
8
9
10
11
2022-02-24T06:09:07.397+0800: 20937.153: [GC (CMS Initial Mark) [1 CMS-initial-mark: 14200895K(13.54G)] 14442312K(13.77G), 0.0209709 secs] [Times: user=0.31 sys=0.00, real=0.02 secs]
2022-02-24T06:09:07.419+0800: 20937.175: [CMS-concurrent-mark-start]
2022-02-24T06:09:07.919+0800: 20937.675: [CMS-concurrent-mark: 0.494/0.500 secs] [Times: user=6.09 sys=0.30, real=0.50 secs]
2022-02-24T06:09:07.919+0800: 20937.675: [CMS-concurrent-preclean-start]
2022-02-24T06:09:07.949+0800: 20937.705: [CMS-concurrent-preclean: 0.030/0.030 secs] [Times: user=0.18 sys=0.02, real=0.03 secs]
2022-02-24T06:09:07.951+0800: 20937.707: [CMS-concurrent-abortable-preclean-start]
2022-02-24T06:09:07.951+0800: 20937.707: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2022-02-24T06:09:07.956+0800: 20937.712: [GC (CMS Final Remark) [YG occupancy: 2093677 K (2146944 K)]2022-02-24T06:09:07.956+0800: 20937.712: [Rescan (parallel) , 0.1065377 secs]2022-02-24T06:09:08.062+0800: 20937.819: [weak refs processing, 0.0001813 secs]2022-02-24T06:09:08.063+0800: 20937.819: [class unloading, 0.0650347 secs]2022-02-24T06:09:08.128+0800: 20937.884: [scrub symbol table, 0.0211737 secs]2022-02-24T06:09:08.149+0800: 20937.905: [scrub string table, 0.0019676 secs][1 CMS-remark: 14200895K(14391744K)] 16294573K(16538688K), 0.1951703 secs] [Times: user=2.94 sys=0.11, real=0.19 secs]
2022-02-24T06:09:08.152+0800: 20937.908: [CMS-concurrent-sweep-start]
2022-02-24T06:09:08.173+0800: 20937.929: [GC (Allocation Failure) 2022-02-24T06:09:08.174+0800: 20937.930: [ParNew: 2146944K->2146944K(2.04G), 0.0000393 secs]2022-02-24T06:09:08.174+0800: 20937.930: [CMS2022-02-24T06:09:44.435+0800: 20974.191: [CMS-concurrent-sweep: 36.264/36.283 secs] [Times: user=34.00 sys=2.45, real=36.29 secs]
(concurrent mode failure): 14200895K->1622463K(14391744K), 44.2843088 secs] 16347839K->1622463K(16538688K), [Metaspace: 105201K->105201K(1146880K)], 45.2549480 secs] [Times: user=40.51 sys=4.75, real=45.26 secs]

造成gc时间较长的主要原因是concurrent mode failure情况下的full gc使用的并不是cms的垃圾回收器,而是使用的Serail-Old垃圾回收器,全程是单线程串行操作。

至于为什么使用Serail-Old?请参考R大的知乎回答

1
2
3
4
先说结论:因为没足够开发资源,偷懒了。就这么简单。没有任何技术上的问题。事实上,还在大量使用CMS GC的公司各自有过若干尝试,把CMS GC配套的备份full GC改进为并行的。阿里巴巴的Ali JDK做了,Google内部使用的OpenJDK也做了。Twitter据说也对CMS GC做了一些优化,不知道他们有没有也自己做过配套备份full GC的并行化;Twitter JDK很快就要开源了,到时候看看就知道。Google的patch在2015年已经提交给了OpenJDK,但是我印象中Oracle直到现在都还没有把它收录到OpenJDK的主干上。

作者:RednaxelaFX
链接:https://www.zhihu.com/question/50398881/answer/120831226

至此原因找到了,那怎么解决呢,首先我们来看看什么是“concurrent mode failure情况”。

concurrent mode failure

该产生的情况有:

  1. 执行CMS GC的过程中有业务线程试图将大的对象放入老年代,CMS在老年带的回收慢于业务对象对老年带内存的分配,而此时老年代空间不足。
  2. Minor GC的时候,新生代Survivor空间放不下,需要放入老年代,而老年代也放不下而产生的(老年代所剩下的空间小于Eden区域+From区域的空间)。(见promotion failed中的例子)
1
2
3
2022-02-24T06:09:08.152+0800: 20937.908: [CMS-concurrent-sweep-start]
2022-02-24T06:09:08.173+0800: 20937.929: [GC (Allocation Failure) 2022-02-24T06:09:08.174+0800: 20937.930: [ParNew: 2146944K->2146944K(2146944K), 0.0000393 secs]2022-02-24T06:09:08.174+0800: 20937.930: [CMS2022-02-24T06:09:44.435+0800: 20974.191: [CMS-concurrent-sweep: 36.264/36.283 secs] [Times: user=34.00 sys=2.45, real=36.29 secs]
(concurrent mode failure): 14200895K->1622463K(14391744K), 44.2843088 secs] 16347839K->1622463K(16538688K), [Metaspace: 105201K->105201K(1146880K)], 45.2549480 secs] [Times: user=40.51 sys=4.75, real=45.26 secs]

例子中是CMS是和业务线程并发运行的,在执行CMS的过程中有业务对象需要在老年带直接分配,例如大对象,但是老年带没有足够的空间来分配,所以导致concurrent mode failure。

当出现concurrent mode failure的现象时,就意味着此时JVM将继续采用Stop-The-World的方式来进行Full GC,这种情况下,CMS就没什么意义了。

解决这个问题的通用方法是调低触发CMS GC执行的阀值,CMS GC触发主要由CMSInitiatingOccupancyFraction值决定,在出现concurrent mode failure的情况下,可考虑调小这个值,提前CMS GC的触发,以保证旧生代有足够的空间。

promotion failed

该问题是在进行Minor GC时,Survivor Space放不下,对象只能放入老年代,而此时老年代也放不下造成的,多数是由于老年带有足够的空闲空间,但是由于碎片较多,这时如果新生代要转移到老年带的对象比较大,所以,必须尽可能提早触发老年代的CMS回收来避免这个问题(promotion failed时老年代CMS还没有机会进行回收,又放不下转移到老年带的对象,因此会出现下一个问题concurrent mode failure,需要stop-the-wold GC- Serail Old)

1
2
2022-02-24T06:05:14.494+0800: 20704.250: [GC (Allocation Failure) 2022-02-24T06:05:14.495+0800: 20704.251: [ParNew (promotion failed): 2146944K->2146944K(2146944K), 3.6292166 secs]2022-02-24T06:05:18.124+0800: 20707.880: [CMS2022-02-24T06:05:26.547+0800: 20716.303: [CMS-concurrent-sweep: 22.077/36.958 secs] [Times: user=328.89 sys=8.16, real=36.96 secs]
(concurrent mode failure): 13685987K->1251286K(14391744K), 20.8081661 secs] 15573183K->1251286K(16538688K), [Metaspace: 105200K->105200K(1146880K)], 25.6102246 secs] [Times: user=34.09 sys=6.22, real=25.61 secs]

一般是进行Minor GC的时候,发现空间不够,所以,需要移动一些新生带的对象到老年带,然而,有些时候尽管老年带有足够的空间,但是由于CMS采用标记清除算法,默认并不使用标记整理算法,可能会产生很多碎片,因此,这些碎片无法完成大对象向老年带转移,因此需要进行CMS在老年带的Full GC来合并碎片。

这个问题的直接影响就是它会导致提前进行CMS Full GC, 尽管这个时候CMS的老年带并没有填满,只不过有过多的碎片而已,但是Full GC导致的stop-the-wold是难以接受的。

解决这个问题的办法就是可以让CMS在进行一定次数的Full GC(标记清除)的时候进行一次标记整理算法,CMS提供了以下参数来控制:

1
-XX:UseCMSCompactAtFullCollection -XX:CMSFullGCBeforeCompaction=5

也就是CMS在进行5次Full GC(标记清除)之后进行一次标记整理算法,从而可以控制老年带的碎片在一定的数量以内,甚至可以配置CMS在每次Full GC的时候都进行内存的整理。

重要参数

-XX:CMSInitiatingOccupancyFraction=70

这个参数是指在使用CMS收集器的情况下,老年代使用了指定阈值的内存时,触发FullGC。默认-1

1
2
3
4
5
6
7
8
9
10
void ConcurrentMarkSweepGeneration::init_initiating_occupancy(intx io, uintx tr) {
assert(io <= 100 && tr <= 100, "Check the arguments");
if (io >= 0) {
_initiating_occupancy = (double)io / 100.0;
} else {
_initiating_occupancy = ((100 - MinHeapFreeRatio) +
(double)(tr * MinHeapFreeRatio) / 100.0)
/ 100.0;
}
}

这个方法的逻辑很简单,就是CMSInitiatingOccupancyFraction大于等于0就走上面分支,否则走下面分支。

如果你自己设置过-XX:CMSInitiatingOccupancyFraction=70,那么最终_initiating_occupancy=70%。在你设置了-XX:+UseCMSInitiatingOccupancyOnly的情况下,老年代内存使用率一旦超过70%就会执行CMS GC了。

如果你没设置过CMSInitiatingOccupancyFraction,默认值-1就走下面分支了。在该分支下还用到一个启动参数:MinHeapFreeRatio。

在JDK1.7(1.7.0_67-b01)和JDK1.8(1.8.0_171)下看了这三个参数的值:
CMSInitiatingOccupancyFraction和CMSTriggerRatio都是-1和80。
但是MinHeapFreeRatio在JDK1.7是0,所以根据公式计算_initiating_occupancy最终得到的值是100%。
而MinHeapFreeRatio在JDK1.8是40,根据公式_initiating_occupancy计算得到的值是92%(68%的可能是其他版本计算得到的值了~)

参考:一个有意思的CMS问题

-XX:+UseCMSCompactAtFullCollection

年老代使用CMS,默认是不会整理堆碎片的。设置此配置打开对年老代的压缩,即执行Full GC后对内存进行整理压缩,免得产生内存碎片,但有可能会影响性能。默认开启

-XX:CMSFullGCsBeforeCompaction=10

因为过于频繁的在Full GC后进行碎片整理会影响性能,代表执行10次Full GC后做一次碎片整理。默认为0,表示每次都进内存整理

-XX:CMSMaxAbortablePrecleanTime=5

指定CMS-concurrent-abortable-preclean阶段执行的时间,该阶段主要是执行一些预清理,减少应用暂停的时间。但在JDK 5.0+、6.0+的版本中有可能会由于JDK的bug29导致CMS在remark完毕后很久才触发sweeping动作。通过设置-XX: CMSMaxAbortablePrecleanTime=5(单位为ms)来避免。默认为5000毫秒