CMS收集器产生的问题和解决方案

垃圾收集器长时间停顿,表现在 Web 页面上可能是页面响应码 500 之类的服务器错误问题,如果是个支付过程可能会导致支付失败,将造成公司的直接经济损失,程序员要尽量避免或者说减少此类情况发生。

提升失败(promotion failed)

在 Minor GC 过程中,Survivor Unused 可能不足以容纳 Eden 和另一个 Survivor 中的存活对象, 那么多余的存货对象将被移到老年代, 称为过早提升(Premature Promotion)。 这会导致老年代中短期存活对象的增长, 可能会引发严重的性能问题。

再进一步,如果老年代没有足够的空间放下这些存活对象,或者老年代有足够的空间,但是由于碎片较多,这时如果新生代要转移到老年带的对象比较大,所以,必须尽可能提早触发老年代的CMS回收来避免这个问题(promotion failed时老年代CMS还没有机会进行回收,又放不下转移到老年带的对象,因此会出现下一个问题concurrent mode failure,需要stop-the-wold GC- Serail Old)。

提升失败日志:

2016-01-07T18:54:26.948+0800: 18782.967: [GC2016-04-07T18:54:26.948+0800: 18782.967: [ParNew (promotion failed) 
Desired survivor size 117833728 bytes, new threshold 10 (max 10) 
- age   1:    6141680 bytes,    6141680 total 
- age   2:    6337936 bytes,   12479616 total 
- age   3:     549120 bytes,   13028736 total 
- age   4:      87768 bytes,   13116504 total 
- age   5:     221384 bytes,   13337888 total 
- age   6:     934168 bytes,   14272056 total 
- age   7:     146072 bytes,   14418128 total 
- age   8:     626064 bytes,   15044192 total 
- age   9:     398000 bytes,   15442192 total 
- age  10:     429616 bytes,   15871808 total 
: 1969227K->1929200K(2071808K), 0.7452140 secs]2016-01-07T18:54:27.693+0800: 18783.713: [CMS: 1394703K->632845K(2097152K), 4.0993640 secs] 3301676K->632845K(4168960K), [CMS Perm : 77485K->77473K(159744K)], 4.8450240 secs] [Times: user=5.18 sys=0.56, real=4.84 secs] 
Heap after GC invocations=5847 (full 7): 
 par new generation   total 2071808K, used 0K [0x00000006e9c00000, 0x0000000776400000, 0x0000000776400000) 
  eden space 1841664K,   0% used [0x00000006e9c00000, 0x00000006e9c00000, 0x000000075a280000) 
  from space 230144K,   0% used [0x0000000768340000, 0x0000000768340000, 0x0000000776400000) 
  to   space 230144K,   0% used [0x000000075a280000, 0x000000075a280000, 0x0000000768340000) 
 concurrent mark-sweep generation total 2097152K, used 632845K [0x0000000776400000, 0x00000007f6400000, 0x00000007f6400000) 
 concurrent-mark-sweep perm gen total 159744K, used 77473K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) 
}

解决方案:

  • 针对一些大的朝生熄灭的对象,Surivor空间存放不下,就会存放到老年代,针对这种情况,可以扩大Survivor空间。
  • 老年代空间碎片,无法放下大对象,就在进行一定次数的Full GC(标记清除)的时候进行一次标记整理算法。

并发模式失败(concurrent mode failure)

由于cms的无法处理浮动垃圾(Floating Garbage)引起的。这个跟cms的机制有关。cms的并发清理阶段,用户线程还在运行,因此不断有新的垃圾产生,而这些垃圾不在这次清理标记的范畴里头,cms无法在本次gc清除掉,这些就是浮动垃圾。由于这种机制,cms年老代回收的阈值不能太高,否则就容易预留的内存空间很可能不够(因为本次gc同时还有浮动垃圾产生),从而导致concurrent mode failure发生。可以通过-XX:CMSInitiatingOccupancyFraction的值来调优。

日志:

2016-02-21T13:53:07.974+0800: 171467.254: [GC [1 CMS-initial-mark: 1436199K(1560576K)] 1512927K(2504320K), 0.0618140 secs] [Times: user=0.06 sys=0.00, real=0.07 secs] 
2016-02-21T13:53:08.036+0800: 171467.316: [CMS-concurrent-mark-start] 
2016-02-21T13:53:08.377+0800: 171467.657: [CMS-concurrent-mark: 0.340/0.340 secs] [Times: user=2.11 sys=0.15, real=0.34 secs] 
2016-02-21T13:53:08.377+0800: 171467.657: [CMS-concurrent-preclean-start] 
2016-02-21T13:53:08.385+0800: 171467.665: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2016-02-21T13:53:08.385+0800: 171467.665: [CMS-concurrent-abortable-preclean-start] 
{Heap before GC invocations=88667 (full 45): 
 par new generation   total 943744K, used 914399K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000) 
  eden space 838912K, 100% used [0x0000000757000000, 0x000000078a340000, 0x000000078a340000) 
  from space 104832K,  72% used [0x000000078a340000, 0x000000078ecf7d98, 0x00000007909a0000) 
  to   space 104832K,   0% used [0x00000007909a0000, 0x00000007909a0000, 0x0000000797000000) 
 concurrent mark-sweep generation total 1560576K, used 1436199K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000) 
 concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) 
2016-02-21T13:53:09.535+0800: 171468.815: [GC2016-02-21T13:53:09.535+0800: 171468.815: [ParNew 
Desired survivor size 53673984 bytes, new threshold 6 (max 6) 
- age   1:    7100568 bytes,    7100568 total 
- age   2:    4676456 bytes,   11777024 total 
- age   3:    8773736 bytes,   20550760 total 
- age   4:    7709744 bytes,   28260504 total 
- age   5:   10891960 bytes,   39152464 total 
- age   6:   11735032 bytes,   50887496 total 
: 914399K->75616K(943744K), 0.0414860 secs] 2350599K->1517225K(2504320K), 0.0417710 secs] [Times: user=0.32 sys=0.05, real=0.05 secs] 
Heap after GC invocations=88668 (full 45): 
 par new generation   total 943744K, used 75616K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000) 
  eden space 838912K,   0% used [0x0000000757000000, 0x0000000757000000, 0x000000078a340000) 
  from space 104832K,  72% used [0x00000007909a0000, 0x0000000795378128, 0x0000000797000000) 
  to   space 104832K,   0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000) 
 concurrent mark-sweep generation total 1560576K, used 1441609K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000) 
 concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) 

2016-02-21T13:53:10.202+0800: 171469.482: [CMS-concurrent-abortable-preclean: 1.772/1.817 secs] [Times: user=4.94 sys=0.06, real=1.81 secs] 
2016-02-21T13:53:10.204+0800: 171469.483: [GC[YG occupancy: 497152 K (943744 K)]2016-02-21T13:53:10.204+0800: 171469.483: [Rescan (parallel) , 1.3691900 secs]2016-02-21T13:53:11.573+0800: 171470.853: [weak refs processing, 0.1009300 secs]2016-02-21T13:53:11.674+0800: 1714 
70.954: [class unloading, 0.0153470 secs]2016-02-21T13:53:11.689+0800: 171470.969: [scrub symbol table, 0.0110770 secs]2016-02-21T13:53:11.700+0800: 171470.980: [scrub string table, 0.0016360 secs] [1 CMS-remark: 1441609K(1560576K)] 1938761K(2504320K), 1.5079530 secs] [Ti 
mes: user=13.01 sys=0.08, real=1.51 secs] 
2016-02-21T13:53:11.712+0800: 171470.992: [CMS-concurrent-sweep-start] 
{Heap before GC invocations=88668 (full 45): 
 par new generation   total 943744K, used 914528K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000) 
  eden space 838912K, 100% used [0x0000000757000000, 0x000000078a340000, 0x000000078a340000) 
  from space 104832K,  72% used [0x00000007909a0000, 0x0000000795378128, 0x0000000797000000) 
  to   space 104832K,   0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000) 
 concurrent mark-sweep generation total 1560576K, used 1441606K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000) 
 concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) 
2016-02-21T13:53:11.775+0800: 171471.055: [GC2016-02-21T13:53:11.775+0800: 171471.055: [ParNew (promotion failed) 
Desired survivor size 53673984 bytes, new threshold 6 (max 6) 
- age   1:    4030872 bytes,    4030872 total 
- age   2:    5959704 bytes,    9990576 total 
- age   3:    4628680 bytes,   14619256 total 
- age   4:    8773080 bytes,   23392336 total 
- age   5:    7707144 bytes,   31099480 total 
- age   6:   10890224 bytes,   41989704 total 
: 914528K->907344K(943744K), 1.0312010 secs]2016-02-21T13:53:12.807+0800: 171472.086: [CMS2016-02-21T13:53:14.455+0800: 171473.735: [CMS-concurrent-sweep: 1.684/2.743 secs] [Times: user=3.69 sys=0.36, real=2.74 secs] 
 (concurrent mode failure): 1451903K->475795K(1560576K), 3.9644230 secs] 2356134K->475795K(2504320K), [CMS Perm : 78413K->78413K(159744K)], 4.9959570 secs] [Times: user=5.65 sys=0.34, real=5.00 secs] 
Heap after GC invocations=88669 (full 46): 
 par new generation   total 943744K, used 0K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000) 
  eden space 838912K,   0% used [0x0000000757000000, 0x0000000757000000, 0x000000078a340000) 
  from space 104832K,   0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000) 
  to   space 104832K,   0% used [0x00000007909a0000, 0x00000007909a0000, 0x0000000797000000) 
 concurrent mark-sweep generation total 1560576K, used 475795K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000) 
 concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000) 
}

解决方案:

  • CMS并发清理阶段,用户线程在年轻代中产生大量对象,大量年轻代中的对象要提升到老年代,老年代的清理速度赶不上年轻代的提升速度,就会造成concurrent mode failure,针对这个问题,
    • 扩大年轻代的空间,提升年轻代的晋升阈值
    • 扩大老年代的空间存放年轻代要晋升的对象,设置 CMS 垃圾收集在老年代占比达到多少时启动来减少问题发生频率(越早启动问题发生频率越低,但是会降低吞吐量,具体得多调整几次找到平衡点)
  • CMS并发清理阶段,年轻代提升上来的大对象,老年代碎片化严重,存放不下,针对这个问题,
    • 一定次数的Full GC(标记清除)的时候进行一次标记整理算法。

总结:

  1. promotion failed造成Full GC,也可能会进一步造成 concurrent mode failure

  2. 注意要尽量避免concurrent mode failure,因为这样会是 CMS收集器转化为Serial Old收集器,Serial Old收集器虽然会压缩老年代空间,但是这个收集器整个过程都是STOP THE World

参考:

JVM 调优 —— GC 长时间停顿问题及解决方法

使用CMS垃圾收集器产生的问题和解决方案

上一篇:bootstrap 操作提示placeholder


下一篇:垃圾收集器之:CMS收集器