公司项目升级到Spring 5.3.x之后,GC次数急剧增加,我TM人傻了

问题背景

最近我们的项目升级到了 Spring Boot 2.4.6 + Spring Cloud 2020.0.x,但是升级后,我们发现 YoungGC 明显增高,分配对象速率明显增高,但是晋升的对象并没有增多,证明都是新创建的对象并且没过多久就可以被回收。我们来看其中一个进程的监控,这时候的 http 请求速率大概在 100 左右:

这就很奇怪了,请求速率并没有那么大,但是通过监控可以看出每秒钟分配了将近两个 G 的内存。在升级之前,这个分配速率大概在 100~200 MB 左右,在同等请求速率下。那么这多出来的内存究竟是从哪里消耗的呢?

定位方式

我们需要看一下内存中各种对象的统计数据,即使用 jmap 命令。同时不能只查看存活对象的统计,因为从监控中看出来并不是老年代对象过多,因为晋升的对象并没有增多,相反的,我们如果我们能排除现在还存活的对象就更好了。同时,由于 GC 相当频繁,1s 左右就会有一次。所以基本不能期望一次就能抓到我们想要的 jmap。同时 jmap 因此导致所有线程进入 safepoint 从而 STW,对线上有一定影响,所以不能太频繁 jmap。所以,我们采取如下策略:

扩容一个实例,之后将一个实例,通过注册中心以及限流器将某个实例的流量切走一半;

针对这个实例,连续执行 jmap -histo(统计所有对象) 以及 jmap -histo:live(仅统计存活对象);

重复第二步 5 次,每次间隔 100ms,300ms,500ms,700ms;

去掉限流这个实例的限流,将新扩容的实例关闭。

通过这几次的 jmap 对比,我们发现 jmap 统计中排在前面的对象类型有一个 spring 框架的:

num#instances        #bytes  class name (module)-------------------------------------------------------1:7993252601860528[B(java.base@11.0.8)2:360025296261160[C(java.base@11.0.8)3:10338806246557984[Ljava.lang.Object;(java.base@11.0.8)4:6314471151547304java.lang.String(java.base@11.0.8)5:48170135607088[J(java.base@11.0.8)6:314420126487344[I(java.base@11.0.8)7:4591109110100264[Ljava.lang.Class;(java.base@11.0.8)8:24554255001408org.springframework.core.ResolvableType9:20523429042280[Ljava.util.HashMap$Node;(java.base@11.0.8)10:38625224720128[org.springframework.core.ResolvableType;11:69992922397728java.sql.Timestamp(java.sql@11.0.8)12:8915021281256[Ljava.beans.PropertyDescriptor;(java.desktop@11.0.8)13:51902916608928java.util.HashMap$Node(java.base@11.0.8)14:59872814369472java.util.ArrayList(java.base@11.0.8)

这个对象是怎么创建出来的呢?如何定位一个已经不再存活的频繁创建对象,并且这个对象类型是框架内部的

首先,MAT(Eclipse Memory Analyzer)+ jmap dump 这种整个堆分析,并不太适用,原因是:

对象已经不再存活,MAT 更适合对于内存泄漏的分析,我们这里是创建出来很多预期外的对象,占用了大量内存,这些对象很快就不再存活。

MAT 对于不再存活的对象,无法准确分析出创建者,主要因为 dump 的时候不确定是否能抓到我们想要的信息,或者有很多信息噪声。

虽然这个问题不能这么定位,我还是将我采集的 jmap dump 结果放在这里用 MAT 分析的结果展示出来给大家看下:

那么接下来怎么分析呢?这就又用到了我们的老朋友,JFR + JMC。老读者知道,我经常使用 JFR 定位线上问题,这里怎么使用呢?并没有直接的 JFR 事件统计经常创建哪些对象,但是呢,有间接的事件,可以间接体现是谁创建了这么多对象。我一般这么定位:

通过线程分配对象统计事件查看是哪个线程分配对象过多(Thread Allocation Statistics)。

通过热点代码分析哪些热点代码可能会产生这些对象(Method Profiling Sample)。像这种大量创建的对象,抓取 Runnable 代码很大概率被抓取到,并且在事件中占比高。

首先查看 Thread Allocation Statistics 事件,发现基本上所有 servlet 线程(就是处理 Http 请求的线程,我们用的 Undertow,所以线程名称是 XNIO 开头的),分配的对象都很多,这样并不能定位问题:

然后我们来看热点代码统计,点击 Method Profiling Sample 事件,查看堆栈追踪统计,看哪些占比比较高。

发现占比靠前的,貌似都和这个 ResolvableType 有关,进一步定位,双击第一个方法查看调用堆栈统计:

我们发现,调用它的是 BeanUtils.copyProperties。查看其它ResolvableType 有关的调用,都和BeanUtils.copyProperties有关。这个方法是我们项目中经常使用的方法,用于同类型或者不同类型之间的属性复制。这个方法为何会创建这么多 ResolvableType 呢?

查看源码与问题定位

通过查看源码,我们发现从 Spring 5.3.x 开始,BeanUtils 开始通过创建 ResolvableType 这个统一类信息封装,进行属性复制:

/**

*

* <p>As of Spring Framework 5.3, this method honors generic type information

*/privatestaticvoidcopyProperties(Object source, Object target,@NullableClass editable,@NullableString... ignoreProperties)throwsBeansException{}

里面的源码,每次都针对源对象和目标对象的类型的每个属性方法创建了新的 ResolvableType,并且没有做缓存。这导致一次复制,会创建出来大量的 ResolvableType.我们来做个试验:

publicclassTest{publicstaticvoidmain(String[] args){        TestBean testBean1 =newTestBean("1","2","3","4","5","6","7","8","1","2","3","4","5","6","7","8");        TestBean testBean2 =newTestBean();for(inti =0; i >-1; i++) {            BeanUtils.copyProperties(testBean1, testBean2);            System.out.println(i);        }    }}

分别使用 spring-beans 5.2.16.RELEASE 和 spring-beans 5.3.9 这两个依赖去执行这个代码,JVM 参数使用 -XX:+

UnlockExperimentalVMOptions -XX:+UseEpsilonGC -Xmx512m.这些参数的意思是,使用 EpsilonGC,也就是在堆内存满的时候,不执行 GC,直接抛出 OutofMemory 异常并程序结束,并且最大堆内存是 512m。这样,程序其实就是看:在内存耗尽之前,不同版本的 BeanUtils.copyProperties 分别能执行多少次

试验结果是:spring-beans 5.2.16.RELEASE 是 444489 次,spring-beans 5.3.9 是 27456 次。这是相当大的差距啊

于是,针对这个问题,我向 spring-framework github 提了个 Issue.

然后,对于项目中经常使用 BeanUtils.copyProperties 的地方,替换成使用 BeanCopier,并且封装了一个简单类:

publicclassBeanUtils{privatestaticfinal Cache CACHE = Caffeine.newBuilder().build();publicstaticvoidcopyProperties(Object source, Object target){        Class sourceClass = source.getClass();        Class targetClass = target.getClass();        BeanCopier beanCopier = CACHE.get(sourceClass.getName() +" to "+ targetClass.getName(), k -> {returnBeanCopier.create(sourceClass, targetClass,false);        });        beanCopier.copy(source, target,null);    }}

但是需要注意的是,BeanCopier替换BeanUtils.copyProperties最直接的一个问题就是:对于属性不同但是名字不同的无法复制。例如一个是 int 另一个是 Integer 也不行。同时还有深拷贝的一些区别,需要我们做好单元测试。

修改好后,问题解决。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,126评论 6 481
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,254评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 152,445评论 0 341
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,185评论 1 278
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,178评论 5 371
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,970评论 1 284
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,276评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,927评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,400评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,883评论 2 323
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,997评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,646评论 4 322
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,213评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,204评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,423评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,423评论 2 352
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,722评论 2 345

推荐阅读更多精彩内容