天天看點

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

作者:散文随風想

# 背景

公司 SpringBoot 項目在日常開發過程中發現服務啟動過程異常緩慢,常常需要6-7分鐘才能暴露端口,嚴重降低開發效率。通過 SpringBoot 的 SpringApplicationRunListener 、BeanPostProcessor 原理和源碼調試等手段排查發現,在 Bean 掃描和 Bean 注入這個兩個階段有很大的性能瓶頸。

通過 JavaConfig 注冊 Bean, 減少 SpringBoot 的掃描路徑,同時基于 Springboot 自動配置原理對第三方依賴優化改造,将服務本地啟動時間從7min 降至40s 左右的過程。本文會涉及以下知識點:

  • 基于 SpringApplicationRunListener 原理觀察 SpringBoot 啟動 run 方法;
  • 基于 BeanPostProcessor 原理監控 Bean 注入耗時;
  • SpringBoot Cache 自動化配置原理;
  • SpringBoot 自動化配置原理及 starter 改造;

# 耗時問題排查

SpringBoot 服務啟動耗時排查,目前有2個思路:

  1. 排查 SpringBoot 服務的啟動過程;
  2. 排查 Bean 的初始化耗時;

1.1 觀察 SpringBoot 啟動 run 方法

該項目使用基于 SpringBoot 改造的内部微服務元件 XxBoot 作為服務端實作,其啟動流程與 SpringBoot 類似,分為 ApplicationContext 構造和 ApplicationContext 啟動兩部分,即通過構造函數執行個體化 ApplicationContext 對象,并調用其 run 方法啟動服務:

public class Application {    public static void main(String[] args) {        SpringApplication.run(Application.class, args);    }}public static ConfigurableApplicationContext run(Class<?>[] primarySources, String[] args) {    return new SpringApplication(primarySources).run(args);}           

ApplicationContext 對象構造過程,主要做了自定義 Banner 設定、應用類型推斷、配置源設定等工作,不做特殊擴充的話,大部分項目都是差不多的,不太可能引起耗時問題。通過在 run 方法中打斷點,啟動後很快就運作到斷點位置,也能驗證這一點。

接下就是重點排查 run 方法的啟動過程中有哪些性能瓶頸?SpringBoot 的啟動過程非常複雜,慶幸的是 SpringBoot 本身提供的一些機制,将 SpringBoot 的啟動過程劃分了多個階段,這個階段劃分的過程就展現在 SpringApplicationRunListener 接口中,該接口将 ApplicationContext 對象的 run 方法劃分成不同的階段:

public interface SpringApplicationRunListener {    // run 方法第一次被執行時調用,早期初始化工作    void starting();    // environment 建立後,ApplicationContext 建立前    void environmentPrepared(ConfigurableEnvironment environment);    // ApplicationContext 執行個體建立,部分屬性設定了    void contextPrepared(ConfigurableApplicationContext context);    // ApplicationContext 加載後,refresh 前    void contextLoaded(ConfigurableApplicationContext context);    // refresh 後    void started(ConfigurableApplicationContext context);    // 所有初始化完成後,run 結束前    void running(ConfigurableApplicationContext context);    // 初始化失敗後    
  void failed(ConfigurableApplicationContext context, Throwable exception);
}           

目前,SpringBoot 中自帶的 SpringApplicationRunListener 接口隻有一個實作類:EventPublishingRunListener,該實作類作用:通過觀察者模式的事件機制,在 run 方法的不同階段觸發 Event 事件,ApplicationListener 的實作類們通過監聽不同的 Event 事件對象觸發不同的業務處理邏輯。

通過自定義實作 ApplicationListener 實作類,可以在 SpringBoot 啟動的不同階段,實作一定的處理,可見SpringApplicationRunListener 接口給 SpringBoot 帶來了擴充性。

這裡我們不必深究實作類 EventPublishingRunListener 的功能,但是可以通過 SpringApplicationRunListener 原理,添加一個自定義的實作類,在不同階段結束時列印下目前時間,通過計算不同階段的運作時間,就能大體定位哪些階段耗時比較高,然後重點排查這些階段的代碼。

先看下 SpringApplicationRunListener 的實作原理,其劃分不同階段的邏輯展現在 ApplicationContext 的 run 方法中:

run 方法中 getRunListeners(args) 通過 SpringFactoriesLoader 加載 classpath 下 META-INF/spring.factotries 中配置的所有 SpringApplicationRunListener 的實作類,通過反射執行個體化後,存到局部變量 listeners 中,其類型為 SpringApplicationRunListeners;然後在 run 方法不同階段通過調用 listeners 的不同階段方法來觸發 SpringApplicationRunListener 所有實作類的階段方法調用。

是以,隻要編寫一個 SpringApplicationRunListener 的自定義實作類,在實作接口不同階段方法時,列印目前時間;并在 META-INF/spring.factotries 中配置該類後,該類也會執行個體化,存到 listeners 中;在不同階段結束時列印結束時間,以此來評估不同階段的執行耗時。

在項目中添加實作類 MySpringApplicationRunListener :

@Slf4j
public class MySpringApplicationRunListener implements SpringApplicationRunListener {
    // 這個構造函數不能少,否則反射生成執行個體會報錯
    public MySpringApplicationRunListener(SpringApplication sa, String[] args) {
    }
    @Override
    public void starting() {
        log.info("starting {}", LocalDateTime.now());
    }
    @Override
    public void environmentPrepared(ConfigurableEnvironment environment) {
        log.info("environmentPrepared {}", LocalDateTime.now());
    }
    @Override
    public void contextPrepared(ConfigurableApplicationContext context) {
        log.info("contextPrepared {}", LocalDateTime.now());
    }
    @Override
    public void contextLoaded(ConfigurableApplicationContext context) {
        log.info("contextLoaded {}", LocalDateTime.now());
    }
    @Override
    public void started(ConfigurableApplicationContext context) {
        log.info("started {}", LocalDateTime.now());
    }
    @Override
    public void running(ConfigurableApplicationContext context) {
        log.info("running {}", LocalDateTime.now());
    }
    @Override
    public void failed(ConfigurableApplicationContext context, Throwable exception) {
        log.info("failed {}", LocalDateTime.now());
    }
}           

這邊 (SpringApplication sa, String[] args) 參數類型的構造函數不能少,因為源碼中限定了使用該參數類型的構造函數反射生成執行個體。

在 resources 檔案下的 META-INF/spring.factotries 檔案中配置上該類:

# Run Listeners
org.springframework.boot.SpringApplicationRunListener=\
com.xxx.ad.diagnostic.tools.api.MySpringApplicationRunListener           

run 方法中是通過 getSpringFactoriesInstances 方法來擷取 META-INF/spring.factotries 下配置的 SpringApplicationRunListener 的實作類,其底層是依賴 SpringFactoriesLoader 來擷取配置的類的全限定類名,然後反射生成執行個體;

這種方式在 SpringBoot 用的非常多,如 EnableAutoConfiguration、ApplicationListener、ApplicationContextInitializer 等。

重新開機服務,觀察 MySpringApplicationRunListener 的日志輸出,發現主要耗時都在 contextLoaded 和 started 兩個階段之間,在這兩個階段之間調用了2個方法:

refreshContext 和 afterRefresh 方法,而 refreshContext 底層調用的是 AbstractApplicationContext#refresh,Spring 初始化 context 的核心方法之一就是這個 refresh。

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

至此基本可以斷定,高耗時的原因就是在初始化 Spring 的 context,然而這個方法依然十分複雜,好在 refresh 方法也将初始化 Spring 的 context 的過程做了整理,并詳細注釋了各個步驟的作用:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

通過簡單調試,很快就定位了高耗時的原因:

  1. 在 invokeBeanFactoryPostProcessors(beanFactory) 方法中,調用了所有注冊的 BeanFactory 的後置處理器;
  2. 其中,ConfigurationClassPostProcessor 這個後置處理器貢獻了大部分的耗時;
  3. 查閱相關資料,該後置處理器相當重要,主要負責@Configuration、@ComponentScan、@Import、@Bean 等注解的解析;
  4. 繼續調試發現,主要耗時都花在主配置類的 @ComponentScan 解析上,而且主要耗時還是在解析屬性 basePackages;
公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

即項目主配置類上 @SpringBootApplication 注解的 scanBasePackages 屬性:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

通過該方法 JavaDoc、檢視相關代碼,大體了解到該過程是在遞歸掃描、解析 basePackages 所有路徑下的 class,對于可作為 Bean 的對象,生成其 BeanDefinition;如果遇到 @Configuration 注解的配置類,還得遞歸解析其 @ComponentScan。至此,服務啟動緩慢的原因就找到了:

  1. 作為資料平台,我們的服務引用了很多第三方依賴服務,這些依賴往往提供了對應業務的完整功能,是以提供的 jar 包非常大;
  2. 掃描這些包路徑下的 class 非常耗時,很多 class 都不提供 Bean,但還是花時間掃描了;
  3. 每添加一個服務的依賴,都會線性增加掃描的時間;

弄明白耗時的原因後,我有2個疑問:

  1. 是否所有的 class 都需要掃描,是否可以隻掃描那些提供 Bean 的 class?
  2. 掃描出來的 Bean 是否都需要?我隻接入一個功能,但是注入了所有的 Bean,這似乎不太合理?

1.2 監控 Bean 注入耗時

第二個優化的思路是監控所有 Bean 對象初始化的耗時,即每個 Bean 對象執行個體化、初始化、注冊所花費的時間,有沒有特别耗時 Bean 對象?

同樣的,我們可以利用 SpringBoot 提供了 BeanPostProcessor 接口來監控 Bean 的注入耗時,BeanPostProcessor 是 Spring 提供的 Bean 初始化前後的 IOC 鈎子,用于在 Bean 初始化的前後執行一些自定義的邏輯:

public interface BeanPostProcessor {
    // 初始化前
    default Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        return bean;
    }
    // 初始化後
    default Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        return bean;
    }   
}           

對于 BeanPostProcessor 接口的實作類,其前後置處理過程展現在 AbstractAutowireCapableBeanFactory#doCreateBean,這也是 Spring 中非常重要的一個方法,用于真正執行個體化 Bean 對象,通過 BeanFactory#getBean 方法一路 Debug 就能找到。在該方法中調用了 initializeBean 方法:

protected Object initializeBean(String beanName, Object bean, @Nullable RootBeanDefinition mbd) {
    ...
    Object wrappedBean = bean;
    if (mbd == null || !mbd.isSynthetic()) {
        // 應用所有 BeanPostProcessor 的前置方法
        wrappedBean = applyBeanPostProcessorsBeforeInitialization(wrappedBean, beanName);
    }
    try {
        invokeInitMethods(beanName, wrappedBean, mbd);
    }
    catch (Throwable ex) {
        throw new BeanCreationException(
                (mbd != null ? mbd.getResourceDescription() : null),
                beanName, "Invocation of init method failed", ex);
    }
    if (mbd == null || !mbd.isSynthetic()) {
        // 應用所有 BeanPostProcessor 的後置方法
        wrappedBean = applyBeanPostProcessorsAfterInitialization(wrappedBean, beanName);
    }
    return wrappedBean;
}           

通過 BeanPostProcessor 原理,在前置處理時記錄下目前時間,在後置處理時,用目前時間減去前置處理時間,就能知道每個 Bean 的初始化耗時,下面是我的實作:

@Component
public class TimeCostBeanPostProcessor implements BeanPostProcessor {
    private Map<String, Long> costMap = Maps.newConcurrentMap();


    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        costMap.put(beanName, System.currentTimeMillis());
        return bean;
    }
    @Override
    public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        if (costMap.containsKey(beanName)) {
            Long start = costMap.get(beanName);
            long cost  = System.currentTimeMillis() - start;
            if (cost > 0) {
                costMap.put(beanName, cost);
                System.out.println("bean: " + beanName + "\ttime: " + cost);
            }
        }
        return bean;
    }
}           

BeanPostProcessor 的邏輯是在 Beanfactory 準備好後處理的,就不需要通過 SpringFactoriesLoader 加載了,直接 @Component 注入即可。

重新開機服務,通過以上方法排查 Bean 初始化過程,還真的有所發現:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

這個 Bean 初始化耗時43s,具體看下這個 Bean 的初始化方法,發現會從資料庫查詢大量配置中繼資料,并更新到 Redis 緩存中,是以初始化非常慢:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

另外,還發現了一些非項目自身服務的service、controller對象,這些 Bean 來自于第三方依賴:UPM服務,項目中并不需要:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

其實,原因上文已經提到:我隻接入一個功能,但我注入了該服務路徑下所有的 Bean,也就是說,服務裡注入其他服務的、對自身無用的 Bean。

# 優化方案

2.1 如何解決掃描路徑過多?

想到的解決方案比較簡單粗暴:

梳理要引入的 Bean,删掉主配置類上掃描路徑,使用 JavaConfig 的方式顯式手動注入。

以 UPM 的依賴為例,之前的注入方式 是,項目依賴其 UpmResourceClient 對象,Pom 已經引用了其 Maven 坐标,并在主配置類上的 scanBasePackages 中添加了其服務路徑:"com.xxx.ad.upm",通過掃描整個服務路徑下的 class,找到 UpmResourceClient 并注入,因為該類注解了 @Service,是以會注入到服務的 Spring 上下文中,UpmResourceClient 源碼片段及主配置類如下:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

使用 JavaConfig 的改造方式是:不再掃描 UPM 的服務路徑,而是主動注入。删除"com.xxx.ad.upm",并在服務路徑下添加以下配置類:

@Configuration
public class ThirdPartyBeanConfig {
    @Bean
    public UpmResourceClient upmResourceClient() {
        return new UpmResourceClient();
    }
}           
Tips:如果該 Bean 還依賴其他 Bean,則需要把所依賴的 Bean 都注入;針對 Bean 依賴情況複雜的場景梳理起來就比較麻煩了,所幸項目用到的服務 Bean 依賴關系都比較簡單,一些依賴關系複雜的服務,觀察到其路徑掃描耗時也不是很高,就不處理了。

同時,通過 JavaConfig 按需注入的方式,就不存在備援 Bean 的情況了,也有利于降低服務的記憶體消耗;解決了上面的引入無關的 upmService、upmController 的問題。

2.2 如何解決 Bean 初始化高耗時?

Bean 初始化耗時高,就需要 case by case 地處理了,比如項目中遇到的初始化配置中繼資料的問題,可以考慮通過将該任務送出到線程池的方式異步處理或者懶加載的方式來解決。

# 新的問題

完成以上優化後,本地啟動時間從之前的 7min 左右降低至 40s,效果還是非常顯著的。本地自測通過後,便釋出到預發進行驗證,驗證過程中,有同學發現項目接入的 Redis 緩存元件失效了。

該元件接入方式與上文描述的接入方式類似,通過添加掃描服務的根路徑"com.xxx.ad.rediscache",注入對應的 Bean 對象;檢視該緩存元件項目的源碼,發現該路徑下有一個 config 類注入了一個緩存管理對象 CacheManager,其實作類是 RedisCacheManager:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

緩存元件代碼片段:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

本次優化中,我是通過 每次删除一條掃描路徑,啟動服務後根據啟動日志中 Bean 缺失錯誤的資訊,來逐個梳理、添加依賴的 Bean,保證服務正常啟動 的方式來改造的,而删除"com.xxx.ad.rediscache"後啟動服務并無異常,是以就沒有進一步的操作,直接上預發驗證了。這就奇怪了,既然不掃描該元件的業務代碼根路徑,也就沒有執行注入該元件中定義的 CacheManager 對象,為啥用到緩存的地方沒有報錯呢?

嘗試在未添加掃描路徑的情況下,從 ApplicationContext 中擷取 CacheManager 類型的對象看下是否存在?結果發現确實存在 RedisCacheManager 對象:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

其實,前面的分析并沒有錯,删除掃描路徑後生成的 RedisCacheManager 并不是緩存元件代碼中配置的,而是 SpringBoot 的自動化配置生成的,也就是說該對象并不是我們想要的對象,是不符合預期的,下文介紹其原因。

3.1 SpringBoot 自動化裝配,讓人防不勝防

查閱 SpringBoot Cache 相關資料,發現 SpringBoot Cache 做了一些自動推斷和注入的工作,原來是 SpringBoot 自動化裝配的鍋呀,接下來就分析下 SpringBoot Cache 原理,明确出現以上問題的原因。

SpringBoot 自動化配置,展現在主配置類上複合注解 @SpringBootApplication 中的@EnableAutoConfiguration 上,該注解開啟了 SpringBoot 的自動配置功能。該注解中的@Import(AutoConfigurationImportSelector.class) 通過加載 META-INF/spring.factotries 下配置一系列 *AutoConfiguration 配置類,根據現有條件推斷,盡可能地為我們配置需要的 Bean。這些配置類負責各個功能的自動化配置,其中用于 SpringBoot Cache 的自動配置類是 CacheAutoConfiguration,接下來重點分析這個配置類就行了。

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

@SpringBootApplication 複合注解中內建了三個非常重要的注解:@SpringBootConfiguration、@EnableAutoConfiguration、@ComponentScan,其中 @EnableAutoConfiguration 就是負責開啟自動化配置功能;

SpringBoot 中有多@EnableXXX 的注解,都是用來開啟某一方面的功能,其實作原理也是類似的:通過 @Import 篩選、導入滿足條件的自動化配置類。

可以看到 CacheAutoConfiguration 上有許多注解,重點關注下@Import({CacheConfigurationImportSelector.class}),CacheConfigurationImportSelector 實作了 ImportSelector 接口,該接口用于動态選擇想導入的配置類,這個 CacheConfigurationImportSelector 用來導入不同類型的 Cache 的自動配置類:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

通過調試 CacheConfigurationImportSelector 發現,根據 SpringBoot 支援的緩存類型(CacheType),提供了10種 cache 的自動配置類,按優先級排序,最終隻有一個生效,而本項目中恰恰就是 RedisCacheConfiguration,其内部提供的是 RedisCacheManager,和引入第三方緩存元件一樣,是以造成了困惑:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

看下 RedisCacheConfiguration 的實作:

公司入職一個大佬,把SpringBoot項目啟動從420秒優化到了40秒!

這個配置類上有很多條件注解,當這些條件都滿足的話,這個自動配置類就會生效,而本項目恰恰都滿足,同時項目主配置類上還加上了 @EnableCaching,開啟了緩存功能,即使緩存元件沒生效,SpringBoot 也會自動生成一個緩存管理對象;

即:緩存元件服務掃描路徑存在的話,緩存元件中的代碼生成緩存管理對象,@ConditionalOnMissingBean(CacheManager.class) 失效;掃描路徑不存在的話,SpringBoot 通過推斷,自動生成一個緩存管理對象。

這個也很好驗證,在 RedisCacheConfiguration 中打斷點,不删除掃描路徑是走不到這邊的SpringBoot 自動裝配過程的(緩存元件顯式生成過了),删除了掃描路徑是能走到的(SpringBoot 自動生成)。

上文多次提到@Import,這是 SpringBoot 中重要注解,主要有以下作用:

1、導入 @Configuration 注解的類;

2、導入實作了 ImportSelector 或 ImportBeanDefinitionRegistrar 的類;

3、導入普通的 POJO。

3.2 使用 starter 機制,開箱即用

了解緩存失效的原因後,就有解決的辦法了,因為是自己團隊的元件,就沒必要通過 JavaConfig 顯式手動導入的方式改造,而是通過 SpringBoot 的 starter 機制,優化下緩存元件的實作,可以做到自動注入、開箱即用。隻要改造下緩存元件的代碼,在 resources 檔案中添加一個 META-INF/spring.factotries 檔案,在下面配置一個 EnableAutoConfiguration 即可,這樣項目在啟動時也會掃描到這個 jar 中的 spring.factotries 檔案,将 XxxAdCacheConfiguration 配置類自動引入,而不需要掃描"com.xxx.ad.rediscache"整個路徑了:

# EnableAutoConfigurations
org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
com.xxx.ad.rediscache.XxxAdCacheConfiguration