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

京东云开发者
• 阅读 291

问题描述

公司某规则引擎系统,在每次发版启动会手动预热,预热完成当流量切进来之后会偶发的出现一次长达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

这里更新了对象晋升年龄阈值为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的总大小,累加规则如下图所示

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

当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。

计算方式为:
给祖传系统做了点 GC调优,暂停时间降低了 90% | 京东云技术团队

变形一下,Eden 的大小计算公式为:

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

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

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

好了,现在直接通过比例,强行给 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 。

参考

作者:京东保险 蒋信

来源:京东云开发者社区 转载请注明来源

点赞
收藏
评论区
推荐文章
双十一预售活动分析
2022年双十一促销活动已经开始,大家应该都提前开始关注今年双十一活动的时间表了吧?2022年10月24日晚8:00天猫双11预售时间,第一波销售时间10月31日晚8:0,第二波销售时间11月10日晚8:00;天猫双11的优惠力度是跨店每满30050
Wesley13 Wesley13
3年前
VBox 启动虚拟机失败
在Vbox(5.0.8版本)启动Ubuntu的虚拟机时,遇到错误信息:NtCreateFile(\\Device\\VBoxDrvStub)failed:0xc000000034STATUS\_OBJECT\_NAME\_NOT\_FOUND(0retries) (rc101)Makesurethekern
Wesley13 Wesley13
3年前
FLV文件格式
1.        FLV文件对齐方式FLV文件以大端对齐方式存放多字节整型。如存放数字无符号16位的数字300(0x012C),那么在FLV文件中存放的顺序是:|0x01|0x2C|。如果是无符号32位数字300(0x0000012C),那么在FLV文件中的存放顺序是:|0x00|0x00|0x00|0x01|0x2C。2.  
Stella981 Stella981
3年前
SpringBoot整合Redis乱码原因及解决方案
问题描述:springboot使用springdataredis存储数据时乱码rediskey/value出现\\xAC\\xED\\x00\\x05t\\x00\\x05问题分析:查看RedisTemplate类!(https://oscimg.oschina.net/oscnet/0a85565fa
Wesley13 Wesley13
3年前
mysql设置时区
mysql设置时区mysql\_query("SETtime\_zone'8:00'")ordie('时区设置失败,请联系管理员!');中国在东8区所以加8方法二:selectcount(user\_id)asdevice,CONVERT\_TZ(FROM\_UNIXTIME(reg\_time),'08:00','0
Easter79 Easter79
3年前
SpringBoot整合Redis乱码原因及解决方案
问题描述:springboot使用springdataredis存储数据时乱码rediskey/value出现\\xAC\\xED\\x00\\x05t\\x00\\x05问题分析:查看RedisTemplate类!(https://oscimg.oschina.net/oscnet/0a85565fa
Wesley13 Wesley13
3年前
Java日期时间API系列36
  十二时辰,古代劳动人民把一昼夜划分成十二个时段,每一个时段叫一个时辰。二十四小时和十二时辰对照表:时辰时间24时制子时深夜11:00凌晨01:0023:0001:00丑时上午01:00上午03:0001:0003:00寅时上午03:00上午0
Stella981 Stella981
3年前
Kubernetes Pod OOM 排查日记
一、发现问题在一次系统上线后,我们发现某几个节点在长时间运行后会出现内存持续飙升的问题,导致的结果就是Kubernetes集群的这个节点会把所在的Pod进行驱逐OOM;如果调度到同样问题的节点上,也会出现Pod一直起不来的问题。我们尝试了杀死Pod后手动调度的办法(label),当然也可以排除调度节点。但是在一段时间后还会复现,我们通过监控
Wesley13 Wesley13
3年前
MySQL部分从库上面因为大量的临时表tmp_table造成慢查询
背景描述Time:20190124T00:08:14.70572408:00User@Host:@Id:Schema:sentrymetaLast_errno:0Killed:0Query_time:0.315758Lock_
Java服务总在半夜挂,背后的真相竟然是... | 京东云技术团队
最近有用户反馈测试环境Java服务总在凌晨00:00左右挂掉,用户反馈Java服务没有定时任务,也没有流量突增的情况,Jvm配置也合理,莫名其妙就挂了