ParNew长时间停顿

Posted by Yuanyeex on Tuesday, November 6, 2018

ParNew是一个比较常用的年轻代垃圾回收器,采用复制算法进行回收。一般ParNew不会占用很高的CPU,之前遇到过的ParNew高CPU的情况也是内存分配很快导致的,这种情况下ParNew的表现是ParNew回收很频繁,单次回收很快。而这次要说的这个情况不是这样,他的GC频率不会太高,但是单次GC花费很长的CPU时间,导致的结果就是服务器CPU使用率打满,这个服务性能降级,负载分担到其他节点。不幸的是,这个症状一段时间后’传染’到其他节点,整个集群的节点一个接一个的跑满CPU,形成一种雪崩效应。

看下面这段日志:


50.335: [GC (Allocation Failure) 50.335: [ParNew: 275197K->3058K(306688K), 4.1443533 secs] 791070K->519212K(2063104K), 4.1443891 secs] [Times: user=13.19 sys=0.08, real=4.14 secs] 
54.514: [GC (Allocation Failure) 54.514: [ParNew: 275698K->2506K(306688K), 3.9621551 secs] 791852K->518941K(2063104K), 3.9621931 secs] [Times: user=13.14 sys=0.06, real=3.96 secs] 
58.519: [GC (Allocation Failure) 58.519: [ParNew: 275146K->3054K(306688K), 4.4037586 secs] 791581K->519766K(2063104K), 4.4038009 secs] [Times: user=14.98 sys=0.07, real=4.41 secs] 
62.962: [GC (Allocation Failure) 62.962: [ParNew: 275694K->3317K(306688K), 4.3245416 secs] 792406K->520309K(2063104K), 4.3245845 secs] [Times: user=15.24 sys=0.07, real=4.32 secs] 

从日志可以看出,一次ParNew耗时4秒,随着运行时间的增长,这个耗时还会越来越长。通过下面的代码可以复现这个问题:

package cc.databus.parnew;

import java.lang.management.ManagementFactory;
import java.lang.management.RuntimeMXBean;
import java.util.ArrayList;
import java.util.List;

/**
 * https://bugs.openjdk.java.net/browse/JDK-8079274
 */
public class AbnormalParnew {
    static byte[] bigStaticObject;

    public static void main(String[] args) throws Exception {

        System.out.println("Process Id: " + getProcessID());

        int bigObjSize = args.length > 0 ? Integer.parseInt(args[0]) : 524288000;
        int littleObjSize = args.length > 1 ? Integer.parseInt(args[1]) : 100;
        int saveFraction = args.length > 2 ? Integer.parseInt(args[2]) : 1000;
        System.out.println("Start allocate large memory");
        bigStaticObject = new byte[bigObjSize];
        System.out.println("Allocate done");
        List<byte[]> holder = new ArrayList<byte[]>();

        long end = System.currentTimeMillis() + 60000; // trigger full gc 1min later
        int i = 0;
        while (true) {
            // 分配内存
            byte[] local = new byte[littleObjSize];
            if (i++ % saveFraction == 0) {
                holder.add(local);
            }
        }
    }

    public static final int getProcessID() {
        RuntimeMXBean runtimeMXBean = ManagementFactory.getRuntimeMXBean();
        return Integer.valueOf(runtimeMXBean.getName().split("@")[0]);
    }

}

复现的逻辑是一次性分配一个大内存,比如500MB,后续的ParNew GC都会有很高的CPU占用。 就算我们把后续分配内存的速率降低,ParNew GC仍然会占用很多CPU,感兴趣可以自己试着调一下。这个问题详情可以参考文献1。

还有一点是,这个问题可以通过触发一次Full GC恢复。在我们hotfix上线之前,我们写了段脚本,定期去触发一把Full GC…..

至于我们是怎么解决这个问题的,其实定位到这里,我们也知道我们的服务什么地方会有大内存的分配,通过业务场景的分析,其实完全可以不去分配那么大的内存,所以我们的hotfix就是保证业务不受影响的情况,不去解析客户的响应内容。这个事故也推动了我们线上服务使用G1作为垃圾回收器。

  1. Long ParNew Pauses When Large Static Object Previously Allocated

「真诚赞赏,手留余香」

Yuanyeex

真诚赞赏,手留余香

使用微信扫描二维码完成支付