一、前言
本文记录了在大促前针对 SpringBoot 应用启动速度过慢而采取的优化方案，主要介绍了如何定位启动速度慢的阻塞点，以及如何解决这些问题。希望可以帮助大家了解如何定位该类问题以及提供一些解决此类问题的思路。下文介绍的 JSF 为京东内部 RPC 框架，类似于阿里的 Dubbo（本文使用的 SpringBoot 版本为 2.6.2）
二、问题背景
1.广告投放平台核心应用生产环境单台机器部署需要 400-500s，加上镜像下载时间大约 1 分钟，整体耗时接近 10 分钟，应用部署时间过长会带来诸多问题，例如上线遇到问题需要进行快速回滚，启动时间过长会延长恢复时间，影响业务的连续性。
2.会导致整个应用的发布时间变长，目前我们这个应用有上百个容器，单次部署编排时间超过半个小时，上线等待时间过长；另一个问题是在测试预发环境联调修改一次编译+部署就要十几分钟，严重影响联调进度，浪费了很多时间。
3.综上所述，可以看出对应用的启动速度优化刻不容缓，浪费时间就是在浪费生命，所以我们必须要做些什么，下面通过一张图先来看下旧的生产集群发布的概况。
三、解决方案
要想排查应用启动速度过慢的问题，需要先定位到是哪里慢，乍看这句话，就和没说一样，其实就是陈述一下事实😀，下面介绍几种常见的排查方法：
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@Slf4jpublic 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@Slf4jpublic 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 初始化变慢，显而易见，肯定是这个注解对应的驱动类做了什么特殊操作导致了变慢，下面我们来分析一下。
1.我们项目中引用了大约 170+的 JSF consumer 接口，@JsfConsumer 注解是我们内部自己定义的一个针对 Cosnumer 接口使用的注解，他的使用方式很简单，只需要在引用的接口上打上这个注解，内部的 starter 会自动的帮你去做 consumer 的 refer，在 RPC 调用中，我们作为消费者去调用生产者，其实我们只是依赖了一个接口，需要在启动的时候调用 refer 方法帮我们去生成代理对象我们才能发起调用，通过翻阅 starter 的源码发现是通过一个 BeanPostProcessor 的 postProcessBeforeInitialization 方法去做的，源码如下
@SneakyThrows@Overridepublic 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); }
} }}
复制代码
2、通过分析上面的代码，可以发现唯一耗时的地方只可能在 refer 方法的调用，所以修改 stater 源码，在 refer 方法执行的前后打印日志，重新部署后查看日志，发现果然就是这个方法执行很慢，有的接口甚至达到了十几秒，因为 spring 容器的初始化是单线程执行，这些时间累加起来就是一个很大的量级，随即阅读 JSF 源码，探究一下为什么会慢。
3、通过从 refer 方法进入，一步步探究，最终找到了和服务端建立连接的代码，，这个方法的大体流程就是找到这个接口所有的提供者，和这些提供者所在的机器建立长连接用于后续的通信，建立的时候使用了多线程，但是如果一个接口对应的提供者太多，或者某些提供者机器不健康了，就可能会导致整个建立连接的时间过长。
4、分析出原因以后，解决方案也就很简单了，既然 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
1、我们项目中除了上述通过 @JsfConsumer 注解生成客户端代理外，还有另外一种方式来生成客户端代理，那就是借助 JSF 自身提供的 ConsumerBean 类，该类实现了 FactoryBean 接口，可以将每个 Jsf Consumer 的配置都生成一个 BeanDefinition 实例，同时设置 BeanDefinition 的 beanClass 属性来使用它，使用这种方法可以确保生成的 bean 一定是单例的，防止上面那种方式可能存在不同类的同一个 JSF Consumer 配置不一致的情况。
2、熟悉 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; }
复制代码
3、还是熟悉的配方，和我们上面分析的调用 refer 方法一模一样，因为 consumer 初始化的核心就是通过 refer 方法生成代理对象，然后客户端持有代理对象，使用的时候通过代理对象去发起远程调用，但是这里有个关键问题就是之前的 refer 方法是我们自己控制的，我们可以任意去修改调用他的位置，但是现在的是 JSF 自己提供的，我们没法修改 JSF 的源码，而且他的触发是容器回调的，那我们该怎么办？
4、其实这个时候我们可以想一下，refer 方法慢，我们想加速，可以和上面一样使用异步模式，但是异步的代码写在哪里，其次是这个方法是容器回调触发，如果我们开启了异步，那容器就得不到真实的引用，会导致错误，那应该怎么解决？
5、这个时候代理的作用就显示出来了，我们其实可以先给容器返回一个我们自己生成的代理对象，然后我们这个代理对象再包装原来 refer 产生的对象，这样客户端实际持有的是我们自己生成的代理对象，而不是 JSF refer 方法产生的代理对象，剩下的最后一步就是仿照原来的 ConsumerBean 魔改一个我们自己的版本，将 getObject 方法的逻辑改为使用线程池导出，同时先返回一个自己的代理对象，其实这种提前返回代理的思想也适用于其他一些场景。
6、我们可以通过一个流程图来梳理一下上面说的流程。
7、魔改后的源码如下，供大家参考
/** * 延迟导出的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; }
}
复制代码
4、玄学-Tomcat 版本问题？
1、我们的这个应用在不同的环境存在两套 tomcat 版本，分别为 8.0.53 和 8.5.42，通过分析不同版本的 tomcat 启动的 debug 日志可以发现，在 8.5.42 版本下，Spring 在实例化对象的时候比在 8.0.53 版本下慢，每个 bean 都慢一点点，我们项目中一共 2900+bean，所以就导致不同的 tomcat 版本也影响启动速度，这块怀疑是高版本的 Tomcat 对于类加载的方式可能有变化导致，换到低版本以后速度就会变快。
5、金钱的力量
1、不同的机房对于应用的启动速度也会有一些影响，如果使用的机器是一些老旧过保的机器，也会对应用的启动速度有影响，使用旧机器也无法保障应用的稳定性，可以将应用迁移到高性能的新机房去，这样可以加快应用启动的速度。
2、在京东内部对比发现，两个不同的机房对于同一个应用启动速度差距非常大，在新机房里面比旧机房快至少 20%。
四、方案总结和效果展示
下面我们来总结一下我们都做了什么
1、Tomcat 启动关闭 TLD 文件扫描。
2、应用启动 Hbase 预热异步化，其实这块我们可以应用到其他场景，大家可以检查下自己的项目启动的时候有没有同步预热的场景。
3、Jsf Consumer 客户端代理 bean 异步生成，此处主要核心在于使用一个自定义代理对象提前返回引用，这种思想我们也可以应用到其他需要异步初始化对象的地方去，具体可以参考 3.2 节的流程图。
4、不同 Tomcat 版本对于应用启动速度的影响。
5、更换到高性能机房对于启动速度的提升。
通过上述的几项优化过后，应用的启动速度得到了大幅改善，下图展示是一个简略的新旧对比，可以看到应用的启动速度从之前 400-500 秒到现在的 130-150s，提升了近 60%多。
评论