大促系統優化之應用啟動速度優化實踐
一、前言
本文記錄了在大促前針對SpringBoot應用啟動速度過慢而采取的優化方案,主要介紹了如何定位啟動速度慢的阻塞點,以及如何解決這些問題。希望可以幫助大家了解如何定位該類問題以及提供一些解決此類問題的思路。下文介紹的JSF為京東內部RPC框架,類似于阿里的Dubbo(本文使用的SpringBoot版本為2.6.2)
二、問題背景
- 廣告投放平臺核心應用生產環境單臺機器部署需要400-500s,加上鏡像下載時間大約1分鐘,整體耗時接近10分鐘,應用部署時間過長會帶來諸多問題,例如上線遇到問題需要進行快速回滾,啟動時間過長會延長恢復時間,影響業務的連續性。
- 會導致整個應用的發布時間變長,目前我們這個應用有上百個容器,單次部署編排時間超過半個小時,上線等待時間過長;另一個問題是在測試預發環境聯調修改一次編譯+部署就要十幾分鐘,嚴重影響聯調進度,浪費了很多時間。
- 綜上所述,可以看出對應用的啟動速度優化刻不容緩,浪費時間就是在浪費生命,所以我們必須要做些什么,下面通過一張圖先來看下舊的生產集群發布的概況。
圖片
三、解決方案
要想排查應用啟動速度過慢的問題,需要先定位到是哪里慢,乍看這句話,就和沒說一樣,其實就是陳述一下事實??,下面介紹幾種常見的排查方法:
1.使用SpringBoot的監控actuator
SpringBoot的actuator是一個監控和管理SpringBoot應用的框架,它提供了許多內置的端點,允許你訪問應用程序的運行時信息,如健康檢查、環境屬性、日志、指標、線程轉儲等,所以我們可以使用其中的一個端點startup去查看整個應用中所有bean的啟動耗時。
但是這種模式下也有個弊端,就是每個bean的加載耗時其實是不準確的,比如A開頭的bean,他的總計耗時會非常的長,原因是因為在這個bean里面去加載其他bean的耗時也會累加到這個bean上,導致數據不準確,所以該方案只能當做參考。(具體該組件的使用方式可以參考該鏈接 點試試 )
2.根據應用的啟動日志分析
這個方法對于項目啟動日志比較少的情況有一定的效果,可以在應用啟動時通過開啟debug日志來逐秒分析,查看啟動日志打印的空白秒,就可以大概定位到阻塞點,定位到耗時的地方后再具體問題具體分析,但是對于大型項目,啟動一次有幾萬行的啟動日志,人工直接分析費時費力,而且還不好定位問題,所以此方法不具有普適性。雖然不好用,但是我們也是可以用一下的,通過這個方面我們定位到了兩處阻塞點。
2.1 Tomcat啟動掃描TLD文件優化
因為我們使用的是外置Tomcat容器,通過查看啟動日志發現Tomcat啟動日志打印的時間和Tomcat引導Spring容器啟動中間隔了幾十秒沒有額外的日志,只有一行 org.apache.jasper.servlet.TldScanner.scanJars: At least one JAR was scanned for TLDs yet none were found. Enable debug logging for this logger to find out which JAR was scanned for TLDs,因為沒有別的日志,只能從這行日志開刀,看這行日志大體的意思是Tomcat在啟動時嘗試掃描某些JAR文件以查找TLD文件,但沒有找到。
那么Tomcat在啟動的時候為什么要掃描TLD文件(什么是TLD文件?點擊這里了解 ),Tomcat 作為 Servlet 規范的實現者,它在應用啟動的時候會掃描 Jar 包里面的 .tld 文件,加載里面定義的標簽庫,但是,我們項目沒有使用 JSP 作為 Web 頁面的模板,為了加快應用的啟動速度,我們可以把 Tomcat 里面的這個功能給關掉那么如何關閉這個掃描以提高啟動速度?,通過查閱文檔發現可以修改Tomcat的catalina.properties文件,
修改一個配置項tomcat.util.scan.StandardJarScanFilter.jarsToSkip設置值為 *.jar就可以關閉掃描。
2.2 應用啟動Hbase異步預熱
通過debug日志發現另一個地方有大約6s的空白,通過查看前后關聯日志發現是在初始化Hbase配置的時候出現的,我們項目中使用的Hbase在應用啟動后第一次訪問會非常慢,原因是在第一次請求時需要緩存元數據到本地,導致接口超時,所以后來就改成了啟動時,實現SmartInitializingSingleton的afterSingletonsInstantiated接口去預熱,但是最早實現的時候使用了localhost線程,所以會阻塞主流程,優化方案很簡單,就是改成起一個異步線程去預熱。
3、使用自定義BeanPostProcessor方案
3.1 @JsfConsumer消費者異步導出
通過上面兩項優化,我們的應用啟動速度有了稍許改善,但是上面的都還是小試牛刀,下面要講的才是真正解決啟動速度過慢的方案。
我們知道Spring容器啟動大體可分為Bean定義的掃描和注冊、bean的實例化、屬性注入、bean的后置處理等,其實真正耗時的部分基本都在bean的后置處理部分,當然有時候對于Bean定義掃描范圍過大也可能會帶來一定的耗時,但是這塊不是本文章的重點部分 ,我們暫時先忽略,那如何去定位是哪些bean的后置處理過慢,我們可以通過增加兩個BeanPostProcess來實現。
通過自定義BeanPostProcess,我們可以在每個bean的初始化前后加埋點,這樣就可以統計出單個bean初始化的耗時情況,具體的方案是使用兩個BeanPostProcess,分別是TimeCostPriorityOrderedBeanPostProcessor、ZLowOrderTimeCostBeanPostProcessor,下面分別來介紹這兩個后置處理器的作用。
我們知道BeanPostProcessor其實有兩個回調方法,我們可以簡單的稱它們為before和after方法,TimeCostPriorityOrderedBeanPostProcessor是一個高優先級的后置處理器,所以會優先執行,我們可以用它來監控容器中所有bean執行BeanPostProcessor的before方法的執行耗時,具體實現也很簡單,就是在這個后置處理器的before方法里面先記錄下每個bean的執行的初始時間,然后在after方法里面計算結束時間,中間的差值就是每個bean執行所有BeanPostProcessor的耗時,具體代碼如下
@Component
@Slf4j
public class TimeCostPriorityOrderedBeanPostProcessor implements BeanPostProcessor, PriorityOrdered {
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 > 50) {
log.info("==>Before方法耗時beanName:{},操作耗時:{}", beanName, cost);
}
}
return bean;
}
@Override
public int getOrder() {
return Integer.MIN_VALUE;
}
}
另外一個后置處理器是ZLowOrderTimeCostBeanPostProcessor ,他基本會最后執行,原因是他沒有實現優先級接口,同時類名還是Z開頭的,我們可以用它來監控容器中所有bean執行BeanPostProcessor的after方法的執行耗時,具體實現方式和上文類似,下面直接貼出源碼
@Component
@Slf4j
public class ZBeanPostProcessor 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 > 50) {
log.info("==>After方法耗時beanName:{},操作耗時:{}", beanName, cost);
}
}
return bean;
}
}
通過在項目中增加上面的兩個BeanPostProcessor,我們重新啟動應用后,發現有很多bean的初始化時間都超過了50ms,再進一步觀察后會發現,這些加載慢的bean基本都有一個共同的特征,那就是這些bean的屬性上面或多或少都帶有@JsfConsumer注解,那么為什么屬性上帶有@JsfConsumer注解會導致這個bean初始化變慢,顯而易見,肯定是這個注解對應的驅動類做了什么特殊操作導致了變慢,下面我們來分析一下。
- 我們項目中引用了大約170+的JSF consumer接口,@JsfConsumer注解是我們內部自己定義的一個針對Cosnumer接口使用的注解,他的使用方式很簡單,只需要在引用的接口上打上這個注解,內部的starter會自動的幫你去做consumer的refer,在RPC調用中,我們作為消費者去調用生產者,其實我們只是依賴了一個接口,需要在啟動的時候調用refer方法幫我們去生成代理對象我們才能發起調用,通過翻閱starter的源碼發現是通過一個BeanPostProcessor的postProcessBeforeInitialization方法去做的,源碼如下
@SneakyThrows
@Override
public Object postProcessBeforeInitialization(@NonNull Object bean, String beanName) throws BeansException {
if (this.isMatchPackage(bean)) {
if (isProvider()) {
this.scanProvider(bean, beanName);
}
if (isConsumer()) {
this.scanConsumer(bean, beanName);
}
}
return bean;
}
private void scanConsumer(Object bean, String beanName) {
Class<?> beanClass = bean.getClass();
Set<Field> fields = getFieldSetWithSuperClassFields(beanClass);
for (Field field : fields) {
boolean accessible = field.isAccessible();
try {
if (!accessible) {
field.setAccessible(true);
}
JsfConsumerTemplate jsfConsumerTemplate = null;
JsfConsumer jsfConsumer = field.getAnnotation(JsfConsumer.class);
if (jsfConsumer != null) {
jsfConsumerTemplate = convert(jsfConsumer, JsfConsumerTemplate.class);
}
if (jsfConsumerTemplate != null) {
logger.info("==> Final consumer config for JSF interface [{}]: {}", beanClass, JSON.toJSONString(jsfConsumerTemplate));
//生成客戶端配置
ConsumerConfig consumerConfig = this.parseAnnotationConsumer(jsfConsumerTemplate, field.getType());
addFilters(beanName, consumerConfig);
//觸發refer方法執行,生成代理對象
Object ref = consumerConfig.refer();
if (ref != null) {
if (!this.beanFactory.containsSingleton(field.getName())) {
//將生成的對象注冊到spring容器
this.beanFactory.registerSingleton(field.getName(), consumerConfig);
}
Object fieldBean = beanFactory.getBean(field.getName());
try {
logger.info("JsfConsumer class {} field {} inject", bean.getClass().getSimpleName(), field.getName());
//將代理對象設置到對應的屬性
field.set(bean, fieldBean);
} catch (IllegalAccessException exp) {
throw new InitErrorException("Set proxy to field error", exp);
}
}
}
} finally {
if (!accessible) {
field.setAccessible(false);
}
}
}
}
- 通過分析上面的代碼,可以發現唯一耗時的地方只可能在refer方法的調用,所以修改stater源碼,在refer方法執行的前后打印日志,重新部署后查看日志,發現果然就是這個方法執行很慢,有的接口甚至達到了十幾秒,因為spring容器的初始化是單線程執行,這些時間累加起來就是一個很大的量級,隨即閱讀JSF源碼,探究一下為什么會慢。
- 通過從refer方法進入,一步步探究,最終找到了和服務端建立連接的代碼,,這個方法的大體流程就是找到這個接口所有的提供者,和這些提供者所在的機器建立長連接用于后續的通信,建立的時候使用了多線程,但是如果一個接口對應的提供者太多,或者某些提供者機器不健康了,就可能會導致整個建立連接的時間過長。
- 分析出原因以后,解決方案也就很簡單了,既然JSF在建立連接的時候使用了線程池,那我們就可以在上面再套一層線程池,這樣refer方法的執行就不會阻塞后續其他流程的執行,只需要保證在應用啟動成功之前我們的異步線程都執行完成即可,具體改動如下
public static final ThreadPoolExecutor CONSUMER_REFER = new ThreadPoolExecutor(
32, 32,
60, TimeUnit.SECONDS,
new LinkedBlockingQueue<>(102400),
ThreadFactories.create("JSF-REFER"),
new ThreadPoolExecutor.CallerRunsPolicy());
/**
* 掃描當前bean的所有屬性,查看該屬性是否攜帶有JsfConsumer注解,如果有的話,需要調用{@link ConsumerConfig#refer()}生成代理,
* 該方法使用了異步線程池進行操作,這樣可以不阻塞localhost線程的執行
* 在進行導出之前使用了synchronized關鍵字鎖住當前字段,防止出現并發,出現并發的情況可能是在兩個bean里面注入了同一個consumer導致
* @param bean
* @param beanName
*/
private void scanConsumer(Object bean, String beanName) {
Class<?> beanClass = bean.getClass();
Set<Field> fields = getFieldSetWithSuperClassFields(beanClass);
for (Field field : fields) {
boolean accessible = field.isAccessible();
//首先將需要處理的字段計數,防止在異步線程丟失
REFER_COUNT.increment();
Future<?> referFuture = CONSUMER_REFER.submit(() -> {
try {
if (!accessible) {
field.setAccessible(true);
}
JsfConsumerTemplate jsfConsumerTemplate = null;
JsfConsumer jsfConsumer = field.getAnnotation(JsfConsumer.class);
if (jsfConsumer != null) {
jsfConsumerTemplate = convert(jsfConsumer, JsfConsumerTemplate.class);
}
if (jsfConsumerTemplate != null) {
//鎖住當前字段,防止多線程并發導出導致異常
synchronized (field.getType()) {
logger.info("==> Final consumer config for JSF interface [{}]: {}", beanClass, JSON.toJSONString(jsfConsumerTemplate));
ConsumerConfig consumerConfig = this.parseAnnotationConsumer(jsfConsumerTemplate, field.getType());
addFilters(beanName, consumerConfig);
Object ref = consumerConfig.refer();
if (ref != null) {
if (!this.beanFactory.containsSingleton(field.getName())) {
this.beanFactory.registerSingleton(field.getName(), consumerConfig);
}
Object fieldBean = beanFactory.getBean(field.getName());
try {
logger.info("JsfConsumer class {} field {} inject", bean.getClass().getSimpleName(), field.getName());
field.set(bean, fieldBean);
} catch (IllegalAccessException var18) {
throw new InitErrorException("Set proxy to field error", var18);
}
}
}
}
} finally {
if (!accessible) {
field.setAccessible(false);
}
//執行完成后減1
REFER_COUNT.decrement();
}
});
//加到future里面 會監聽ContextRefreshedEvent判斷異步任務是否都已經完成
REFER_FUTURE.add(referFuture);
}
}
/**
* 監聽容器刷新事件
*
* @param contextRefreshedEvent the event to respond to
*/
@Override
@Order(Ordered.LOWEST_PRECEDENCE)
public synchronized void onApplicationEvent(@NonNull ContextRefreshedEvent contextRefreshedEvent) {
logger.info("==> Ready for JSF consumer refer! Application name: {} count:{}", contextRefreshedEvent.getApplicationContext().getApplicationName(), REFER_FUTURE.size());
CONSUMER_REFER.allowCoreThreadTimeOut(true);
try {
int i = 100;
boolean isDone = false;
while (i-- > 0) {
if (REFER_COUNT.sum() == 0) {
isDone = true;
break;
}
Thread.sleep(100);
}
if (!isDone) {
throw new InitErrorException(Strings.format("init jsf consumer error, undo sum :[{}]", REFER_COUNT.sum()));
}
for (Future<?> future : REFER_FUTURE) {
future.get();
}
} catch (Exception exp) {
// 在Web應用中,容器可能是一個父子容器,因此關閉上下文時需要遞歸往上遍歷,把父容器也一起收拾掉
logger.error("<== Exception while batch exporting JSF refer!", exp instanceof ApplicationException ? exp.getCause() : exp);
ApplicationContext toClose = contextRefreshedEvent.getApplicationContext();
while (toClose instanceof ConfigurableApplicationContext) {
ApplicationContext parentApplicationContext = toClose.getParent();
try {
((ConfigurableApplicationContext) toClose).close();
} catch (Exception closeExp) {
logger.error("<== Exception while close application context: {}", toClose.getDisplayName(), closeExp);
}
toClose = parentApplicationContext;
}
return;
}
}
3.2 魔改JSF自帶的ConsumerBean
- 我們項目中除了上述通過@JsfConsumer注解生成客戶端代理外,還有另外一種方式來生成客戶端代理,那就是借助JSF自身提供的ConsumerBean類,該類實現了FactoryBean接口,可以將每個JsfConsumer的配置都生成一個BeanDefinition實例,同時設置BeanDefinition的beanClass屬性來使用它,使用這種方法可以確保生成的bean一定是單例的,防止上面那種方式可能存在不同類的同一個JSF Consumer配置不一致的情況。
- 熟悉Spring源碼的小伙伴都知道,容器刷新的時候會使用BeanDefinition里面的beanClass屬性來實例化對象,這里我們指定這個屬性為ConsumerBean.class,等到容器刷新初始化對象完成后,會繼續判斷該對象是否實現了FactoryBean接口,我們用的這個肯定實現了,然后會觸發該對象getObject方法調用,那么我們就看下JSF自帶的這個FactoryBean的getObject方法都做了些什么,源碼如下
/**
* 根據config實例化所需的Reference實例<br/>
* 返回的應該是具備全操作能力的接口代理實現類對象
*
* @see org.springframework.beans.factory.FactoryBean#getObject()
*/
@Override
@JSONField(serialize = false)
public T getObject() throws Exception {
object = CommonUtils.isUnitTestMode() ? null : refer();
return object;
}
- 還是熟悉的配方,和我們上面分析的調用refer方法一模一樣,因為consumer初始化的核心就是通過refer方法生成代理對象,然后客戶端持有代理對象,使用的時候通過代理對象去發起遠程調用,但是這里有個關鍵問題就是之前的refer方法是我們自己控制的,我們可以任意去修改調用他的位置,但是現在的是JSF自己提供的,我們沒法修改JSF的源碼,而且他的觸發是容器回調的,那我們該怎么辦?
- 其實這個時候我們可以想一下,refer方法慢,我們想加速,可以和上面一樣使用異步模式,但是異步的代碼寫在哪里,其次是這個方法是容器回調觸發,如果我們開啟了異步,那容器就得不到真實的引用,會導致錯誤,那應該怎么解決?
- 這個時候代理的作用就顯示出來了,我們其實可以先給容器返回一個我們自己生成的代理對象,然后我們這個代理對象再包裝原來refer產生的對象,這樣客戶端實際持有的是我們自己生成的代理對象,而不是JSF refer方法產生的代理對象,剩下的最后一步就是仿照原來的ConsumerBean魔改一個我們自己的版本,將getObject方法的邏輯改為使用線程池導出,同時先返回一個自己的代理對象,其實這種提前返回代理的思想也適用于其他一些場景。
- 我們可以通過一個流程圖來梳理一下上面說的流程。
圖片
- 魔改后的源碼如下,供大家參考。
/**
* 延遲導出的ConsumerBean
* 該類的getObject方法會返回一個自定義的代理對象
*/
public class DelayConsumerBean<T> extends ConsumerConfig<T> implements InitializingBean, FactoryBean<T>, ApplicationContextAware, DisposableBean, BeanNameAware {
private static final long serialVersionUID = 6835324481364430812L;
private static final Logger LOGGER = LoggerFactory.getLogger(DelayConsumerBean.class);
private ApplicationContext applicationContext;
@Setter
protected transient String beanName;
private transient T object;
private transient Class objectType;
public static final List<Future<?>> REFER_FUTURE_LIST = Lists.newArrayList();
public static final ThreadPoolExecutor CONSUMER_REFER_EXECUTOR = new ThreadPoolExecutor(
32, 32,
60, TimeUnit.SECONDS,
new LinkedBlockingQueue<>(102400),
ThreadFactories.create("JSF-REFER-2"),
new ThreadPoolExecutor.CallerRunsPolicy());
@JSONField(
serialize = false
)
@SuppressWarnings("unchecked")
public T getObject() throws Exception {
Class<T> consumerInterfaceClass = ClassLoaderUtils.forName(this.interfaceId);
//先生成一個代理對象
T delayConsumer = (T) Proxy.newProxyInstance(
consumerInterfaceClass.getClassLoader(),
new Class[]{consumerInterfaceClass},
new DelayConsumerInvocationHandler()
);
//使用異步線程refer
REFER_FUTURE_LIST.add(CONSUMER_REFER_EXECUTOR.submit(() -> {
super.refer();
}));
object = CommonUtils.isUnitTestMode() ? null : delayConsumer;
//返回提前生成的代理對象
return object;
}
private class DelayConsumerInvocationHandler implements InvocationHandler {
@Override
public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
if (method.getDeclaringClass() == Object.class) {
return method.invoke(DelayConsumerBean.this, args);
}
if (DelayConsumerBean.this.proxyIns == null) {
throw new RuntimeException("DelayConsumerBean.this.proxyIns is null");
}
try {
//客戶端發起調用后,觸發真實的consumer代理執行
return method.invoke(DelayConsumerBean.this.proxyIns, args);
} catch (InvocationTargetException exp) {
throw exp.getTargetException();
} catch (Exception ex) {
throw ApplicationException.mirrorOf(ex);
}
}
}
/**
* 等待所有的任務完成,確保所有的consumer都refer成功了
* @param contextRefreshedEvent
*/
public static void waitForRefer(ContextRefreshedEvent contextRefreshedEvent) {
CONSUMER_REFER_EXECUTOR.allowCoreThreadTimeOut(true);
LOGGER.info("==> Ready for JSF consumer 2 refer! Application name: {} count:{}", contextRefreshedEvent.getApplicationContext().getApplicationName(), REFER_FUTURE_LIST.size());
try {
for (Future<?> future : REFER_FUTURE_LIST) {
future.get();
}
} catch (Exception exp) {
// 在Web應用中,容器可能是一個父子容器,因此關閉上下文時需要遞歸往上遍歷,把父容器也一起關閉
LOGGER.error("<== Exception while batch exporting JSF provider!", exp instanceof ApplicationException ? exp.getCause() : exp);
ApplicationContext toClose = contextRefreshedEvent.getApplicationContext();
while (toClose instanceof ConfigurableApplicationContext) {
ApplicationContext parentApplicationContext = toClose.getParent();
try {
((ConfigurableApplicationContext) toClose).close();
} catch (Exception closeExp) {
LOGGER.error("<== Exception while close application context: {}", toClose.getDisplayName(), closeExp);
}
toClose = parentApplicationContext;
}
}
}
protected DelayConsumerBean() {
}
public void setApplicationContext(ApplicationContext appContext) throws BeansException {
this.applicationContext = appContext;
}
}
我們的這個應用在不同的環境存在兩套tomcat版本,分別為8.0.53和8.5.42,通過分析不同版本的tomcat啟動的debug日志可以發現,在8.5.42版本下,Spring在實例化對象的時候比在8.0.53版本下慢,每個bean都慢一點點,我們項目中一共2900+bean,所以就導致不同的tomcat版本也影響啟動速度,這塊懷疑是高版本的Tomcat對于類加載的方式可能有變化導致,換到低版本以后速度就會變快。
5.金錢的力量
- 不同的機房對于應用的啟動速度也會有一些影響,如果使用的機器是一些老舊過保的機器,也會對應用的啟動速度有影響,使用舊機器也無法保障應用的穩定性,可以將應用遷移到高性能的新機房去,這樣可以加快應用啟動的速度。
- 在京東內部對比發現,兩個不同的機房對于同一個應用啟動速度差距非常大,在新機房里面比舊機房快至少20%。
四、方案總結和效果展示
下面我們來總結一下我們都做了什么
- Tomcat啟動關閉TLD文件掃描。
- 應用啟動Hbase預熱異步化,其實這塊我們可以應用到其他場景,大家可以檢查下自己的項目啟動的時候有沒有同步預熱的場景。
- JsfConsumer客戶端代理bean異步生成,此處主要核心在于使用一個自定義代理對象提前返回引用,這種思想我們也可以應用到其他需要異步初始化對象的地方去,具體可以參考3.2節的流程圖。
- 不同Tomcat版本對于應用啟動速度的影響。
- 更換到高性能機房對于啟動速度的提升。
通過上述的幾項優化過后,應用的啟動速度得到了大幅改善,下圖展示是一個簡略的新舊對比,可以看到應用的啟動速度從之前400-500秒到現在的130-150s,提升了近60%多。
(優化后)
(優化前)