大促实战之应用启动速度优化 | 京东零售技术实践
1.广告投放平台应用生产环境单台机器部署需要400-500s,加上镜像下载时间大约1分钟,整体耗时接近10分钟,应用部署时间过长会带来诸多问题,例如上线遇到问题需要进行快速回滚,启动时间过长会延长恢复时间,影响业务的连续性。
2.会导致整个应用的发布时间变长,目前我们这个应用有上百个容器,单次部署编排时间超过半个小时,上线等待时间过长;另一个问题是在测试预发环境联调修改一次编译+部署就要十几分钟,严重影响联调进度,浪费了很多时间。
3.综上所述,可以看出对应用的启动速度优化刻不容缓,浪费时间就是在浪费生命,所以我们必须要做些什么,下面通过一张图先来看下旧的生产集群发布的概况。
要想排查应用启动速度过慢的问题,需要先定位到是哪里慢,乍看这句话,就和没说一样,其实就是陈述一下事实😀,下面介绍几种常见的排查方法:
2.1 使用SpringBoot的监控actuator
SpringBoot的actuator是一个监控和管理SpringBoot应用的框架,它提供了许多内置的端点,允许你访问应用程序的运行时信息,如健康检查、环境属性、日志、指标、线程转储等,所以我们可以使用其中的一个端点startup去查看整个应用中所有bean的启动耗时。
但是这种模式下也有个弊端,就是每个bean的加载耗时其实是不准确的,比如A开头的bean,他的总计耗时会非常的长,原因是因为在这个bean里面去加载其他bean的耗时也会累加到这个bean上,导致数据不准确,所以该方案只能当做参考。
2.2 根据应用的启动日志分析
这个方法对于项目启动日志比较少的情况有一定的效果,可以在应用启动时通过开启debug日志来逐秒分析,查看启动日志打印的空白秒,就可以大概定位到阻塞点,定位到耗时的地方后再具体问题具体分析,但是对于大型项目,启动一次有几万行的启动日志,人工直接分析费时费力,而且还不好定位问题,所以此方法不具有普适性。虽然不好用,但是我们也是可以用一下的,通过这个方面我们定位到了两处阻塞点。
2.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文件,Tomcat 作为 Servlet 规范的实现者,它在应用启动的时候会扫描 Jar 包里面的 .tld 文件,加载里面定义的标签库,但是,我们项目没有使用 JSP 作为 Web 页面的模板,为了加快应用的启动速度,我们可以把 Tomcat 里面的这个功能给关掉那么如何关闭这个扫描以提高启动速度?,通过查阅文档发现可以修改Tomcat的catalina.properties文件,修改一个配置项tomcat.util.scan.StandardJarScanFilter.jarsToSkip设置值为 *.jar就可以关闭扫描。
2.2.2 应用启动Hbase异步预热
通过debug日志发现另一个地方有大约6s的空白,通过查看前后关联日志发现是在初始化Hbase配置的时候出现的,我们项目中使用的Hbase在应用启动后第一次访问会非常慢,原因是在第一次请求时需要缓存元数据到本地,导致接口超时,所以后来就改成了启动时,实现SmartInitializingSingleton的afterSingletonsInstantiated接口去预热,但是最早实现的时候使用了localhost线程,所以会阻塞主流程,优化方案很简单,就是改成起一个异步线程去预热。
2.3 使用自定义BeanPostProcessor方案
2.3.1 @JsfConsumer消费者异步导出
通过上面两项优化,我们的应用启动速度有了稍许改善,但是上面的都还是小试牛刀,下面要讲的才是真正解决启动速度过慢的方案。
我们知道Spring容器启动大体可分为Bean定义的扫描和注册、bean的实例化、属性注入、bean的后置处理等,其实真正耗时的部分基本都在bean的后置处理部分,当然有时候对于Bean定义扫描范围过大也可能会带来一定的耗时,但是这块不是本文章的重点部分 ,我们暂时先忽略,那如何去定位是哪些bean的后置处理过慢,我们可以通过增加两个BeanPostProcess来实现。
通过自定义BeanPostProcess,我们可以在每个bean的初始化前后加埋点,这样就可以统计出单个bean初始化的耗时情况,具体的方案是使用两个BeanPostProcess,分别是TimeCostPriorityOrderedBeanPostProcessor、ZLowOrderTimeCostBeanPostProcessor,下面分别来介绍这两个后置处理器的作用。
@Component@Slf4jpublic class TimeCostPriorityOrderedBeanPostProcessor implements BeanPostProcessor, PriorityOrdered {private Map<String, Long> costMap = Maps.newConcurrentMap();@Overridepublic Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {costMap.put(beanName, System.currentTimeMillis());return bean;}@Overridepublic 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;}@Overridepublic int getOrder() {return Integer.MIN_VALUE;}}
@Component@Slf4jpublic class ZBeanPostProcessor implements BeanPostProcessor {private Map<String, Long> costMap = Maps.newConcurrentMap();@Overridepublic Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {costMap.put(beanName, System.currentTimeMillis());return bean;}@Overridepublic 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初始化变慢,显而易见,肯定是这个注解对应的驱动类做了什么特殊操作导致了变慢,下面我们来分析一下。
@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方法进入,一步步探究,最终找到了和服务端建立连接的代码,,这个方法的大体流程就是找到这个接口所有的提供者,和这些提供者所在的机器建立长连接用于后续的通信,建立的时候使用了多线程,但是如果一个接口对应的提供者太多,或者某些提供者机器不健康了,就可能会导致整个建立连接的时间过长。
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);}//执行完成后减1REFER_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;}}
2.3.2 魔改JSF自带的ConsumerBean
(1)我们项目中除了上述通过@JsfConsumer注解生成客户端代理外,还有另外一种方式来生成客户端代理,那就是借助JSF自身提供的ConsumerBean类,该类实现了FactoryBean接口,可以将每个Jsf Consumer的配置都生成一个BeanDefinition实例,同时设置BeanDefinition的beanClass属性来使用它,使用这种方法可以确保生成的bean一定是单例的,防止上面那种方式可能存在不同类的同一个JSF Consumer配置不一致的情况。
/*** 根据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;}
(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;@Setterprotected 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());//使用异步线程referREFER_FUTURE_LIST.add(CONSUMER_REFER_EXECUTOR.submit(() -> {super.refer();}));object = CommonUtils.isUnitTestMode() ? null : delayConsumer;//返回提前生成的代理对象return object;}private class DelayConsumerInvocationHandler implements InvocationHandler {@Overridepublic 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;}}
2.4 玄学-Tomcat版本问题?
我们的这个应用在不同的环境存在两套tomcat版本,分别为8.0.53和8.5.42,通过分析不同版本的tomcat启动的debug日志可以发现,在8.5.42版本下,Spring在实例化对象的时候比在8.0.53版本下慢,每个bean都慢一点点,我们项目中一共2900+bean,所以就导致不同的tomcat版本也影响启动速度,这块怀疑是高版本的Tomcat对于类加载的方式可能有变化导致,换到低版本以后速度就会变快。
2.5 金钱的力量
不同的机房对于应用的启动速度也会有一些影响,如果使用的机器是一些老旧过保的机器,也会对应用的启动速度有影响,使用旧机器也无法保障应用的稳定性,可以将应用迁移到高性能的新机房去,这样可以加快应用启动的速度。两个不同的机房对于同一个应用启动速度差距非常大,在新机房里面比旧机房快至少20%。
下面我们来总结一下我们都做了什么
5. 更换到高性能机房对于启动速度的提升。
通过上述的几项优化过后,应用的启动速度得到了大幅改善,提升了近60%。
推荐阅读
Taro 鸿蒙技术内幕系列(二):如何让 W3C 标准的 CSS跑在鸿蒙上
Java方法设计原则与实践:从Effective Java到团队案例