单元测试效率:Spring 工程启动耗时统计"/>
优化单元测试效率:Spring 工程启动耗时统计
相关文章:
- Java Agent 的简单使用
本文相关代码地址:
单元测试在软件项目的可持续发展中扮演着不可或缺的角色,这一点毫无疑问。不久前,公司大佬在内部分享时也提到过:单元测试是每个研发工程师的基本技能。
然而,在实际的开发过程中,我们发现很多研发人员并不愿意编写单元测试。其中一个普遍的原因是很多单元测试需要启动 Spring 容器(而许多 Mock 工具本身并不好用),导致启动过程非常耗时。
以我们的核心项目为例,一次单元测试的运行时间接近 5 分钟。考虑到一般需求开发涉及多个接口,再加上中间调试的时间,可能测试几个接口就会耗费一整天的时间。这严重影响了研发工作的效率。
[2023-10-23 12:34:07] [xxx_release] [Dongguabai.local] [INFO] [dfe7d0de51f548dd90e31411312acbd1] 705c1661f4044444b10b53009a32e8e1 main org.springframework.boot.StartupInfoLogger.logStarted(StartupInfoLogger.java:57) - Started SrvCustomerMapperProxyTest in 277.059 seconds (JVM running for 279.544) [12:34:07.659]
也有同学吐槽过:
本文就是希望可以解决这一痛点问题。
切入点
现在的问题是我们的项目启动 Spring 容器慢,那么我们就需要知道启动到底慢在哪里,结合 Spring 的生命周期,就需要去统计每个 Bean 实例化的时间,有几种很常见的切入点:
-
基于
BeanPostProcessor
BeanPostProcessor
提供了两个函数可以帮助我们在 Bean 实例化之后,属性赋值前做一些事情,这也是网上很多博客介绍的一种方案,但是这个方案有个细节要注意,一个 Bean 可能被多个BeanPostProcessor
去处理,所以要注意计算耗时的BeanPostProcessor
的postProcessBeforeInitialization
是第一个调用,且postProcessAfterInitialization
是最后一个调用。这里就涉及到多个BeanPostProcessor
处理的顺序问题。在 Spring 容器中,多个
BeanPostProcessor
,它们的执行顺序是:postProcessBeforeInitialization
方法:按照BeanPostProcessor
在 Spring 容器中的注册顺序依次执行。InitializingBean.afterPropertiesSet
方法:这是Bean初始化后调用的方法。- Bean 配置中的
init-method
:如果有配置,则执行该方法。 postProcessAfterInitialization
方法:按照BeanPostProcessor
在 Spring 容器中的注册顺序依次执行。
很明显,与我们期望的计算耗时的 BeanPostProcessor
的 postProcessBeforeInitialization
和 postProcessAfterInitialization
的执行顺序是有冲突的,所以需要特殊处理。当然如果实际场景影响不大,直接基于 BeanPostProcessor
来做问题也不大。
-
基于
InstantiationStrategy
它负责基于默认构造器,实例化 Bean。需要在
instantiate
函数执行前后进行统计,但整体实现相对比较复杂 -
基于
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#doCreateBean
统计的时间范围太宽了,属性赋值的情况也会计入其中,不太准确
-
其实以上三点皆有缺陷,在业务系统中,每个 Bean 的耗时点可能各不一样,有的在实例化阶段,有的在初始化阶段(初始化又分多种情况,如
@PostConstruct
、afterPropertiesSet
,init-method
)。所以这几块要单独统计,便于真正知道 Bean 初始化的耗时
耗时统计实现思路
其实耗时统计说白了就是在方法前后记录一下时间,然后求出差值即可。很常见的方案就是基于代理模式去做,但无论是基于 BeanPostProcessor
还是 InstantiationStrategy
其实都需要考虑 Spring 很多基础组件的顺序问题,相对比较麻烦。本文是基于 Java Agent 实现(关于 Java Agent 可以参看:Java Agent 的简单使用),对 Bean 的实例化和初始化两个阶段分别统计耗时。
耗时记录拦截器:
package blog.dongguabai.spring.bean.timestatistics;import net.bytebuddy.implementation.bind.annotation.AllArguments;
import net.bytebuddy.implementation.bind.annotation.Argument;
import net.bytebuddy.implementation.bind.annotation.Origin;
import net.bytebuddy.implementation.bind.annotation.RuntimeType;
import net.bytebuddy.implementation.bind.annotation.SuperCall;
import net.bytebuddy.implementation.bind.annotation.This;import java.lang.reflect.Method;
import java.util.Objects;
import java.util.concurrent.Callable;/*** @author dongguabai* @date 2023-10-22 14:18*/
public class BeanLifeInterceptor {@RuntimeTypepublic static Object intercept(@Origin Method method, @SuperCall Callable<?> callable, @Argument(1) String beaName, @AllArguments Object[] args, @This Object obj) throws Exception {long start = System.currentTimeMillis();try {return callable.call();} finally {long end = System.currentTimeMillis();if (Objects.equals(method.getName(), "instantiate")) {instantiateLog(beaName, end - start);}if (Objects.equals(method.getName(), "postProcessBeforeInitialization")) {beforeInitializationLog(beaName, start);}if (Objects.equals(method.getName(), "postProcessAfterInitialization")) {afterInitializationLog(beaName, end);}}}private synchronized static void instantiateLog(String beaName, long time) {Log log = LogInterceptor.logs.get(beaName);if (log == null) {log = new Log(beaName);}TimeDate timeDate = log.getTimeDate();timeDate.setBeanName(beaName);timeDate.setInstantiateTime(time);LogInterceptor.logs.put(beaName, log);}private synchronized static void beforeInitializationLog(String beaName, long time) {Log log = LogInterceptor.logs.get(beaName);if (log == null) {log = new Log(beaName);}log.setStartInitializationTime(Math.min(log.getStartInitializationTime() == 0L ? Long.MAX_VALUE : log.getStartInitializationTime(), time));LogInterceptor.logs.put(beaName, log);}private synchronized static void afterInitializationLog(String beaName, long time) {Log log = LogInterceptor.logs.get(beaName);if (log == null) {log = new Log(beaName);}log.setEndInitializationTime(Math.max(time, log.getEndInitializationTime()));LogInterceptor.logs.put(beaName, log);}
}
装载耗时记录拦截器:
package blog.dongguabai.spring.bean.timestatistics;import net.bytebuddy.agent.builder.AgentBuilder;
import net.bytebuddy.implementation.MethodDelegation;
import net.bytebuddy.matcher.ElementMatchers;import java.lang.instrument.Instrumentation;/*** @author dongguabai* @date 2023-10-22 14:19*/
public class PreMainAgent {public static void premain(String agentArgs, Instrumentation inst) {new AgentBuilder.Default().type(ElementMatchers.hasSuperType(ElementMatchers.named("org.springframework.beans.factory.support.InstantiationStrategy"))).transform((builder, typeDescription, classLoader, javaModule) -> builder.method(ElementMatchers.named("instantiate")).intercept(MethodDelegation.to(BeanLifeInterceptor.class))).type(ElementMatchers.hasSuperType(ElementMatchers.named("org.springframework.beans.factory.config.InstantiationAwareBeanPostProcessorAdapter"))).transform((builder, typeDescription, classLoader, javaModule) -> builder.method(ElementMatchers.named("postProcessBeforeInitialization").or(ElementMatchers.named("postProcessAfterInitialization"))).intercept(MethodDelegation.to(BeanLifeInterceptor.class))).installOn(inst);new AgentBuilder.Default().type(ElementMatchers.named(agentArgs.split("#")[0])).transform((builder, typeDescription, classLoader, javaModule) -> builder.method(ElementMatchers.named(agentArgs.split("#")[1])).intercept(MethodDelegation.to(LogInterceptor.class))).installOn(inst);}
}
将 Agent 工程进行打包:
➜ spring-bean-timestatistics mvn package
[INFO] Scanning for projects...
...
[WARNING] Replacing pre-existing project main-artifact file: /Users/dongguabai/IdeaProjects/github/spring-bean-timestatistics/target/dongguabai-spring-bean-timestatistics-1.0-SNAPSHOT.jar
with assembly file: /Users/dongguabai/IdeaProjects/github/spring-bean-timestatistics/target/dongguabai-spring-bean-timestatistics-1.0-SNAPSHOT.jar
...
查看耗时
在启动单元测试时,增加 VM options:
-javaagent:/Users/dongguabai/IdeaProjects/github/spring-bean-timestatistics/target/dongguabai-spring-bean-timestatistics-1.0-SNAPSHOT.jar=com.xxx.SrvCustomerMapperProxyTest#testInsert
这里 com.xxx.SrvCustomerMapperProxyTest
是指要代理的类,testInsert
是指要代理的函数。
接下来启动单元测试看看效果(可以看到这次启动居然只用了 200s,也说明每次启动的时间都不稳定):
...
[2023-10-24 18:04:45] [maf_release] [Dongguabai.local] [INFO] [b4f3a146566b46a49214e48ffabfb615] 06df0988e4364d499d90aa4f7b702b2f main org.springframework.boot.StartupInfoLogger.logStarted(StartupInfoLogger.java:57) - Started SrvCustomerMapperProxyTest in 199.152 seconds (JVM running for 204.326) [18:04:45.346]
...
BEANS TIME STATISTICS:
【shardingDatasourceRoutingDataSource-> totalTime=50526, instantiateTime=76, initializeTime=50450】
【basicDataDubboService-> totalTime=5876, instantiateTime=0, initializeTime=5876】
【com.alibaba.boot.dubbo.DubboProviderAutoConfiguration-> totalTime=4641, instantiateTime=0, initializeTime=4641】
【orgBaseManager-> totalTime=4481, instantiateTime=0, initializeTime=4481】
【srvCommonDubboServiceImpl-> totalTime=2845, instantiateTime=17, initializeTime=2828】
【storageProxyService-> totalTime=2708, instantiateTime=0, initializeTime=2708】...
可以看到各个 Bean 实例化和初始化的耗时,接下来要做的就是逐个分析降低它们的耗时,这就比较简单了。
耗时分析
这里分析几个 Top 耗时。
shardingDatasourceRoutingDataSource
可以看到耗时在 initializeTime
,而这个 Bean 实现了 AbstractRoutingDataSource
,重写了 afterPropertiesSet
方法:
private void initDataSource(DruidDataSource druidDataSource) {try {druidDataSource.init();} catch (SQLException e) {throw new RuntimeException(e);}}
而耗时主要就在连接池初始化,这个其实有两种方案:
-
异步初始化
设置一下即可,但是这个要注意,可能我们跑单测的时候涉及到数据库访问,如果此时连接池没有初始化完成的话会出现异常
druidDataSource.setAsyncInit(true);
-
初始化连接数为 0
就是不需要一开始就设置数据库连接:
ds.setInitialSize(NumberUtils.toInt(env.getProperty("ds.initialSize"), 10));
我这边使用第二种方案。
basicDataDubboService
这是一个普通被 @Service
标注的 Bean,可以看到也是耗时在 initializeTime
,这是因为这个项目使用的是自己封装的 Dubbo 接口,依赖注入 Dubbo Reference 是依赖于 BeanPostProcessor
实现。
在 basicDataDubboService
中引入 Dubbo 接口方式是使用的自定义注解 @DubboConsumer
:
@Service
@Slf4j
public class BasicDataDubboService {@DubboConsumer(check = false) private FaultService faultService;
}
而 @DubboConsumer
会被 BeanPostProcessor
处理:
@Beanpublic BeanPostProcessor beanPostProcessor() {return new BeanPostProcessor() {@Overridepublic Object postProcessBeforeInitialization(Object bean, String beanName)throws BeansException {Class<?> objClz = bean.getClass();if (org.springframework.aop.support.AopUtils.isAopProxy(bean)) {objClz = org.springframework.aop.support.AopUtils.getTargetClass(bean);}try {for (Field field : objClz.getDeclaredFields()) {DubboConsumer dubboConsumer = field.getAnnotation(DubboConsumer.class);
...
分析后可以设置 @DubboConsumer
属性 lazy
为 true
,相当于 ReferenceBean
的 lazy
属性,这样可以懒加载创建 Reference 代理。
同时也发现有很多无用的注入,这里可以直接清除:
com.alibaba.boot.dubbo.DubboProviderAutoConfiguration
这个也是团队内部封装的 Dubbo 配置类,它依赖 @PostConstruct
对外暴露 Dubbo 服务:
@PostConstructpublic void init() throws Exception {Map<String, Object> beans = this.applicationContext.getBeansWithAnnotation(Service.class);for (Map.Entry<String, Object> entry : beans.entrySet()) {this.initProviderBean(entry.getKey(), entry.getValue());if(this.properties.getProviderDefaultGroup()){this.initProviderBeanWithGroup(entry.getKey(), entry.getValue());}}}
private void initProviderBeanWithGroup(String beanName, Object bean) throws Exception {...serviceConfig.export();}
可以看到整个实现也是相对比较粗糙(比如根本没必要获取全部的 @Service
标注的 Bean,可以自定义一个实现注解,降低查找范围),先不纠结于细节,至少本地启动单元测试是没必要暴露 Dubbo 服务的,所以是否暴露 Dubbo 服务可以基于 profile 做一个限制。
结果查看
上面三耗时分析,除了 com.alibaba.boot.dubbo.DubboProviderAutoConfiguration
由于涉及到代码改造,暂时没有处理,其余的两个已经处理,重新启动,看看效果:
...
[2023-10-24 18:52:03] [maf_release] [Dongguabai.local] [INFO] [d53b3ebcc40240f19b12ca0bdf434436] 375000afa08a48b49f9121a5c4760386 main org.springframework.boot.StartupInfoLogger.logStarted(StartupInfoLogger.java:57) - Started SrvCustomerMapperProxyTest in 142.282 seconds (JVM running for 148.136) [18:52:03.086]
...
【basicDataDubboService-> totalTime=5567, instantiateTime=0, initializeTime=5567】
【shardingDatasourceRoutingDataSource-> totalTime=272, instantiateTime=70, initializeTime=202】
...
可以看到整个启动速度大大提升,主要还是 shardingDatasourceRoutingDataSource
的初始化速度从 50450ms 降低至 202ms。至于 basicDataDubboService
,效果相对一般,但也从中找到了内部封装的 Dubbo 组件优化点。
总结
基于 TOP3 耗时 Bean 的分析来看,耗时有这么几种原因:
- 数据库连接可以延迟初始化
- 移除无用的依赖注入
- 内部封装的 Dubbo 组件存在很多优化点,如:
- Dubbo Provider 在本地没必要对外暴露服务
- 懒加载创建 Reference 代理
尽管不同项目的耗时原因各有差异,但只要能够确定具体的耗时点,问题就不会太棘手。本文介绍了一个简单的工具,用于获取 Spring Bean 初始化的时间,借此能够准确定位具体的 Bean,从而有针对性地进行优化。通过优化这些耗时操作,就能够有效提升整个项目的启动速度,显著增强研发工作的效率。
References
欢迎关注公众号:
更多推荐
优化单元测试效率:Spring 工程启动耗时统计
发布评论