一次年轻代GC长暂停问题的解决与思考

时间 2020-09-29 标签一次年轻代 gc 长暂停问题解决思考

问题描述

公司某规则引擎系统，在每次发版启动会手动预热，预热完成当流量切进来以后会偶发的出现一次长达1-2秒的年轻代GC（流量并不大，而且LB下的每一台服务都会出现该状况）java

在此次长暂停以后，每一次的年轻代GC暂停时间又都恢复在20-100ms之内算法

2s虽然看起来不长，可是对比规则引擎每次10ms左右的响应时间来讲，仍是不能够接受的；而且因为该规则引擎响应超时，还会致使出单超时失败jvm

问题分析

在分析该系统GC日志后发现，2s暂停发生在Young GC阶段，并且每次发生长暂停的Young GC都会伴随着新生代对象的晋升(Promotion)测试

核心JVM参数（Oracle JDK7）this

-Xms10G 
-Xmx10G 
-XX:NewSize=4G 
-XX:PermSize=1g 
-XX:MaxPermSize=4g 
-XX:+UseConcMarkSweepGC

启动后第一次年轻代GC日志spa

2020-04-23T16:28:31.108+0800: [GC2020-04-23T16:28:31.108+0800: [ParNew2020-04-23T16:28:31.229+0800: [SoftReference, 0 refs, 0.0000950 secs]2020-04-23T16:28:31.229+0800: [WeakReference, 1156 refs, 0.0001040 secs]2020-04-23T16:28:31.229+0800: [FinalReference, 10410 refs, 0.0103720 secs]2020-04-23T16:28:31.240+0800: [PhantomReference, 286 refs, 2 refs, 0.0129420 secs]2020-04-23T16:28:31.253+0800: [JNI Weak Reference, 0.0000000 secs]
Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age   1:  315529928 bytes,  315529928 total
- age   2:   40956656 bytes,  356486584 total
- age   3:    8408040 bytes,  364894624 total
: 3544342K->374555K(3774912K), 0.1444710 secs] 3544342K->374555K(10066368K), 0.1446290 secs] [Times: user=1.46 sys=0.09, real=0.15 secs]

长暂停年轻代GC日志.net

2020-04-23T17:18:28.514+0800: [GC2020-04-23T17:18:28.514+0800: [ParNew2020-04-23T17:18:29.975+0800: [SoftReference, 0 refs, 0.0000660 secs]2020-04-23T17:18:29.975+0800: [WeakReference, 1224 refs, 0.0001400 secs]2020-04-23T17:18:29.975+0800: [FinalReference, 8898 refs, 0.0149670 secs]2020-04-23T17:18:29.990+0800: [PhantomReference, 600 refs, 1 refs, 0.0344300 secs]2020-04-23T17:18:30.025+0800: [JNI Weak Reference, 0.0000210 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age   1:   79203576 bytes,   79203576 total
: 3730075K->304371K(3774912K), 1.5114000 secs] 3730075K->676858K(10066368K), 1.5114870 secs] [Times: user=6.32 sys=0.58, real=1.51 secs]

从这个长暂停的GC日志来看，是发生了晋升的，在Young GC后，有363M+的对象晋升到了老年代，这个晋升操做因该就是耗时缘由（ps: 检查过safepoint缘由，不存在异常）指针

因为日志参数中没有配置-XX:+PrintHeapAtGC参数，这里是手动计算的晋升大小：日志

年轻代年轻变化 - 全堆容量变化 = 晋升大小
(304371K - 3730075K) - (676858K - 3730075K) = 372487K(363M)code

下一次年轻代GC日志

2020-04-23T17:23:39.749+0800: [GC2020-04-23T17:23:39.749+0800: [ParNew2020-04-23T17:23:39.774+0800: [SoftReference, 0 refs, 0.0000500 secs]2020-04-23T17:23:39.774+0800: [WeakReference, 3165 refs, 0.0002720 secs]2020-04-23T17:23:39.774+0800: [FinalReference, 3520 refs, 0.0021520 secs]2020-04-23T17:23:39.776+0800: [PhantomReference, 150 refs, 1 refs, 0.0051910 secs]2020-04-23T17:23:39.782+0800: [JNI Weak Reference, 0.0000100 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age   1:   17076040 bytes,   17076040 total
- age   2:   40832336 bytes,   57908376 total
: 3659891K->90428K(3774912K), 0.0321300 secs] 4032378K->462914K(10066368K), 0.0322210 secs] [Times: user=0.30 sys=0.00, real=0.03 secs]

乍一看其实没什么问题，仔细想一想发现了一些不正常，为何程序刚启动第二次gc就发生了晋升呢

这里应该是动态年龄断定致使的，GC中晋升年龄阈值并非固定的15，而是jvm每次gc后动态计算的

年轻代晋升机制

为了能更好地适应不一样程序的内存情况，虚拟机并非永远地要求对象的年龄必须达到了MaxTenuringThreshold才能晋升老年代，若是在Survivor空间中相同年龄全部对象大小的总和大于Survivor空间的一半，年龄大于或等于该年龄的对象就能够直接进入老年代，无须等到MaxTenuringThreshold中要求的年龄
《深刻理解Java虚拟机》一书中提到，对象晋升年龄的阈值是动态断定的。

不过经查阅其余资料和验证后，发现此处和《深刻理解Java虚拟机》解释的有些出入（或者是书上解释的不够清楚）

其实就是按年龄给对象分组，取total（累加值，小于等与当前年龄的对象总大小）最大的年龄分组，若是该分组的total大于survivor的一半，就将晋升年龄阈值更新为该分组的年龄

注意：不是是超过survivor一半就晋升，超过survivor一半只会从新设置晋升阈值（threshold），在下一次GC才会使用该新阈值

3544342K->374555K(3774912K), 0.1444710 secs] 年轻代

3544342K->374555K(10066368K), 0.1446290 secs] 全堆

从上面第一次的GC日志也能够证实这个结论，在此次GC中全堆的内存变化和年轻代内存变化是相等的，因此并无发生对象的晋升

就像上面的日志中，第一次GC只是将threshold设置为1，由于此时survivor一半为214728704 bytes，而年龄为1的对象总和有315529928 bytes，超过了Desired survivor size，因此在本次GC后将threshold设置为年龄为1的对象年龄1

这里更新了对象晋升年龄阈值为1

Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age   1:  315529928 bytes,  315529928 total
- age   2:   40956656 bytes,  356486584 total
- age   3:    8408040 bytes,  364894624 total

这里顺便解释下这个年龄分布的输出内容：

- age 1: 315529928 bytes, 315529928 total

age 1表示年龄为1的对象分组，315529928 bytes表示年龄为1的对象占用内存大小

315529928 total这个是一个累加值，表示小于等于当前分组年龄的对象总大小。先把对象按年龄分组，age 1的分组total为age 1总大小（前面的xxx bytes），age 2的分组total为age 1 + age 2总大小，age n的分组total为age 1 + age 2 + ... +age n的总大小，累加规则以下图所示

当total最大的分组的total值超过了survivor/2时，就会更新晋升阈值

在第二次年轻代GC“长暂停年轻代GC日志”中，因为新的晋升年龄阈值为1，因此那些经历了一次GC并存活而且如今仍然可达（reachable）的对象们就会发生晋升了

因为这次GC发生了363M的对象晋升，因此致使了长暂停

思考

JVM中这个“动态对象年龄断定”真的是合理的吗？我的认为机制是好的，能够更好的适应不一样程序的内存情况，但不是任何场景都适合，好比在本文中这个刚启动不就GC的场景下就会有问题

由于在程序刚启动时，大多数对象年龄都是0或者1，很容易出现年龄为1的大量存活对象；在这个“动态对象年龄断定”机制下，就会致使新的晋升阈值被设置为1，致使这些不应晋升的对象发生了晋升

好比程序在初始化，正在加载各类资源时发生了Young GC，加载逻辑还在执行中，不少新建的对象年龄在此次GC时仍是可达的（reachable）

经历了此次GC后，这些对象年龄更新为1，可是因为“动态对象年龄断定”机制的影响，晋升年龄阈值更新为了“最大的对象年龄分组”的年龄，也就是这批刚经历了一次GC的对象们

在此次GC以后不久，资源初始化完成了，涉及的相关对象有极可能不可达了，可是因为刚才晋升年龄阈值被更新为了1，在下一次正常的Young GC这批年龄为1的对象会直接发生晋升，提早或者说错误的发生了晋升

解决方案

经查阅文档、资料，发现“动态年龄断定”这个机制并不能禁用，因此若是想解决这个问题，只有靠“绕过”这个计算规则了

动态年龄的断定，是根据Survivor空间中相同年龄全部对象大小的总和大于Survivor空间的一半来断定的，那么根据这个机制解决也很简单

因为咱们足够了解本身的系统，清楚的知道加载资源所需的大概内存，彻底能够设定一个大于这些暂时可达的对象总和的数值来做为survivor的容量

好比上面的日志中，第一次GC后年龄为1的对象有315529928 Bytes(300M)，Desired survivor size为（survivor size /2）214728704 bytes(204M)，那么survivor就能够设置为600M以上。

不过为了稳妥，仍是将survivor调到800M，这样desired survivor size就是400M左右，在第一次Young GC后，就不会因年龄为1的对象总和超过了desired survivor size而致使晋升年龄阈值的更新了，从而也就不会有提早/错误晋升而致使的GC长暂停问题

survivor不能够直接指定大小，不过能够经过-XX:SurvivorRatio这种调节比例的方式来调节survivor大小

-XX:SurvivorRatio=8

表示两个Survivor和Edgen区的比，8表示两个Survivor:Eden=2:8，即一个Survivor占新生代的1/10。

计算方式为：

Survivor Size(1) = Young Generation Size / (2+SurvivorRatio)
Eden Size = Young Generation Size / (2+SurvivorRatio) * SurvivorRatio

扩展阅读

为何晋升300M比年轻代回收3G还要慢这么多倍
根据复制算法的特性，复制算法的时间消耗主要取决于存活对象的大小，而不是总空间的大小

好比上面4G的年轻代（实际只有Eden+S0可用），GC时只须要从GC ROOTS开始遍历对象图，将可达的对象复制至S1便可，并不须要遍历整个年轻代

在上面那次长暂停GC日志中，发生了363M的晋升，300M左右的回收，对比第一次GC基本能够得出，花费的1.5S基本上都是在晋升操做

那么为何晋升操做这么耗时呢？

这里没有深刻研究Oracle JVM实现的年轻代晋升细节，不过晋升涉及跨代复制（其实都年轻代和老年代都是heap，在复制这件事上本质上没什么区别，都是memcpy而已，只是须要额外处理的逻辑更多了）
，所需处理的逻辑会更复杂一些，好比指针的更新等操做，更耗时也是能够理解的，

本地代码模拟

这里也附上一段能够在本地模拟问题的代码，Oracle JDK7下可直接运行测试

//jdk7.。

import java.io.IOException;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;

public class PromotionTest {
    public static void main(String[] args) throws IOException {
        //模拟初始化资源场景
        List<Object> dataList = new ArrayList<>();
        for (int i = 0; i < 5; i++) {
            dataList.add(new InnerObject());
        }
        //模拟流量进入场景
        for (int i = 0; i < 73; i++) {
            if(i == 72){
                System.out.println("Execute young gc...Adjust promotion threshold to 1");
            }
            new InnerObject();
        }
        System.out.println("Execute full gc...dataList has been promoted to cms old space");
        //这里注意dataList中的对象在此次Full GC后会进入老年代
        System.gc();
    }
    public static byte[] createData(){
        int dataSize = 1024*1024*4;//4m
        byte[] data = new byte[dataSize];
        for (int j = 0; j < dataSize; j++) {
            data[j] = 1;
        }
        return data;
    }
    static class InnerObject{
        private Object data;

        public InnerObject() {
            this.data = createData();
        }
    }
}

jvm options

-server -Xmn400M -XX:SurvivorRatio=9 -Xms1000M -Xmx1000M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime -XX:+UseConcMarkSweepGC

看完三件事❤️

若是你以为这篇内容对你还蛮有帮助，我想邀请你帮我三个小忙：

点赞，转发，有大家的『点赞和评论』，才是我创造的动力。
关注公众号『 java烂猪皮』，不按期分享原创知识。
同时能够期待后续文章ing🚀