背景:
springboot项目中由于需要加入了ShardingSphere,之后就发现项目启动时间由之前的十多秒,延长到了70秒左右,去除ShardingSphere之后又恢复十多秒。一直以为是ShardingSphere的问题,网上搜罗了各种信息,也有启动慢的情况,但和我本地情况并不符合。
无奈之下只能上神器了,我的问题出在启动的过程中,还好arthas只要有进程就可以接入,具体排查过程如下:
1、启动项目后以最快的速度启动arthas并attach进程
2、寻找trace的入口点
本来是打算直接从启动类trace的,实际操作过程中启动项目之后再接入arthas的话根本就来不及去trace启动类,所以只能另寻他法。鉴于spring项目启动的时候都是从bean的初始化开始的,所以直接就从bean的初始化入手,执行以下命令:
trace org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory doCreateBean -n 50000 --skipJDKMethod false >> /tmp/a.txt
从日志上找出了慢的地方:
这是啥bean居然要初始化45秒之多,那就watch看一下是哪个bean的初始化过程要这么长时间,重启程序,执行以下命令:
watch org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory initializeBean '{params}' -n 5000000 -x 10 -s >> /tmp/c.txt
通过日志找出是dslContext这个bean初始化,类是DefaultDSLContext过慢:
百度了一番dslContext,查看了DefaultDSLContext的源码,这个类是真的大,5000多行代码,851个方法。于是跟着bean初始化的源代码看看这个初始化过程是哪里出现了问题,org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory:applyBeanPostProcessorsAfterInitialization,跟踪的时候我把耗时打出来,发现这里是由于项目中的一个自定义切片,切片中的切点匹配规则扫描到DefaultDSLContext了,就对其每个方法进行了匹配,851个方法在匹配的时候有些耗时长有些耗时短,大概是这样式的:
一个方法的匹配居然要消耗超过1秒, 这不太科学,我没有继续往下研究了,改掉了切片的匹配规则,不扫描这个类,就解决问题了,这个类本来也不在我的自定义切片的管理范围以内。再往下就需要去看切点规则的匹配逻辑了。
总结:我的问题是引入ShardingSphere带来了新的bean初始化,自定义切片的切点匹配验证的过程中这个新的bean匹配时间过长,导致的项目启动慢,最终解决是修改切点的匹配规则绕过这个不需要匹配的类。
arthas不愧是诊断神器!哈哈