优化单元测试效率：Spring 工程启动耗时统计

编程入门行业动态更新时间:2024-10-27 16:33:31

优化<a href=https://www.elefans.com/category/jswz/34/1771349.html style= 单元测试效率：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 ，它们的执行顺序是：
1. postProcessBeforeInitialization 方法：按照 BeanPostProcessor 在 Spring 容器中的注册顺序依次执行。
2. InitializingBean.afterPropertiesSet 方法：这是Bean初始化后调用的方法。
3. Bean 配置中的 init-method：如果有配置，则执行该方法。
4. 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 组件优化点。