给祖传系统做了点 GC 调优，暂停时间降低了 90% | 京东云技术团队

作者：京东科技开发者

2023-12-13
北京
本文字数：5109 字
阅读完需：约 17 分钟

问题描述

公司某规则引擎系统，在每次发版启动会手动预热，预热完成当流量切进来之后会偶发的出现一次长达 1-2 秒的 Young GC（流量并不大，并且 LB 下的每个节点都会出现该情况）

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

2 秒虽然看起来不算长吧，但规则引擎每次执行也才几毫秒，这谁能忍？而且这玩意一旦超时，出单可能也跟着超时失败！

问题分析

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

核心 JVM 参数（Oracle JDK7）

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

复制代码

可能有人会问，为什么给这么大内存？祖传代码，内存小了跑不动！

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

2023-04-23T16:28:31.108+0800: [GC2023-04-23T16:28:31.108+0800: [ParNew2023-04-23T16:28:31.229+0800: [SoftReference, 0 refs, 0.0000950 secs]2023-04-23T16:28:31.229+0800: [WeakReference, 1156 refs, 0.0001040 secs]2023-04-23T16:28:31.229+0800: [FinalReference, 10410 refs, 0.0103720 secs]2023-04-23T16:28:31.240+0800: [PhantomReference, 286 refs, 2 refs, 0.0129420 secs]2023-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 日志

2023-04-23T17:18:28.514+0800: [GC2023-04-23T17:18:28.514+0800: [ParNew2023-04-23T17:18:29.975+0800: [SoftReference, 0 refs, 0.0000660 secs]2023-04-23T17:18:29.975+0800: [WeakReference, 1224 refs, 0.0001400 secs]2023-04-23T17:18:29.975+0800: [FinalReference, 8898 refs, 0.0149670 secs]2023-04-23T17:18:29.990+0800: [PhantomReference, 600 refs, 1 refs, 0.0344300 secs]2023-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)

复制代码

下一次年轻代 GC 日志

2023-04-23T17:23:39.749+0800: [GC2023-04-23T17:23:39.749+0800: [ParNew2023-04-23T17:23:39.774+0800: [SoftReference, 0 refs, 0.0000500 secs]2023-04-23T17:23:39.774+0800: [WeakReference, 3165 refs, 0.0002720 secs]2023-04-23T17:23:39.774+0800: [FinalReference, 3520 refs, 0.0021520 secs]2023-04-23T17:23:39.776+0800: [PhantomReference, 150 refs, 1 refs, 0.0051910 secs]2023-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

这里更新了对象晋升年龄阈值为1Desired 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。

计算方式为：

变形一下，Eden 的大小计算公式为：

这里用一张堆叠柱状图来详细的解释 SurvivorRatio 不同数值下 Eden/Survivor 的空间比例：

好了，现在直接通过比例，强行给 Survivor 调大

-XX:SurvivorRatio=3

复制代码

调整之后，Survivor 总占比为 40%，大小为 1717829632 Bytes，单个 S0/S1 的一半也有 10% - 429457408 Bytes，远超 age=1 的分组总大小 315529928 Bytes。

这样一来， Young GC 后复制到 Survivor 的对象（最大年龄分组）占总比例的大小就不会到 50% 了，也就不会把 MaxTenuringThreshold 更新为 1 ，自然就解决了这个“乱晋升”的问题**

改完收工，再次发版手动预热后，再也没有切量后长暂停的问题了，Young GC 稳定在 30-100ms，成功解决！

扩展

为什么晋升 300M 比年轻代回收 3G 还要慢这么多倍

根据复制算法的特性，复制算法的时间消耗主要取决于存活对象的大小，而不是总空间的大小

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

复制算法的详细介绍可以参考我的另一篇《垃圾回收算法实现之 - 复制算法（完整可运行C语言代码）》

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

为什么晋升操作这么耗时？

晋升毕竟涉及跨代复制啊（其实都年轻代和老年代都是 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

复制代码

注意，文中垃圾回收相关的机制解释，都是基于 HotSpot JVM，Parallel New + CMS Old 。

参考

《深入理解 JAVA 虚拟机》 - 周志明著
https://blog.codecentric.de/en/2012/08/useful-jvm-flags-part-5-young-generation-garbage-collection/

作者：京东保险蒋信
来源：京东云开发者社区转载请注明来源

发布于: 刚刚阅读数: 3

原文链接:【http://xie.infoq.cn/article/58466fcf2cb944be7d7991473】。文章转载请联系作者。

京东科技开发者

关注

拥抱技术，与开发者携手创造未来！ 2018-11-20 加入

我们将持续为人工智能、大数据、云计算、物联网等相关领域的开发者，提供技术干货、行业技术内容、技术落地实践等文章内容。京东云开发者社区官方网站【https://developer.jdcloud.com/】，欢迎大家来玩

发布

暂无评论

创作场景

给祖传系统做了点 GC 调优，暂停时间降低了 90% | 京东云技术团队

问题描述

问题分析

年轻代晋升机制

思考

解决方案

扩展

为什么晋升 300M 比年轻代回收 3G 还要慢这么多倍

本地代码模拟

参考

京东科技开发者

评论