问题的提出
应用启动慢,估计是很多开发同学在平时开发过程中面临的比较痛苦问题之一,本文分享一下个人之前在应用启动优化方面的经验: 如何快速优化应用的启动速度;
启动时间过程分析
找到应用启动的慢的原因,首先都得定位一下慢慢的原因在那里,下面是我们应用latour在aone上一次启动的时间统计:
根据上图应用在 一次启动过程中所花时间主要由拉取镜像时间 + 停止应用时间 + 升级容器时间 + 启动应用时间 + 应用自检时间,其中拉取镜像时间,停止应用时间 ,升级容器时间,应用自检时间,我们暂时是无法做相关的优化,唯一能做的就是针对启动应用的时间进行优化,这个也是占应用启动时间的大头;
方案的选择
由于我们应用绝大部分都用的都是 Spring框架,由于spring bean的创建都是用反射来进行bean创建,bean创建的时间,主要是涉及到类的加载,我们基本上很难做优化,但是bean的初始化这个时间可以控制, 因为重点是放在监控bean的初始化上, 我们大家都知道,Spring框架优秀的扩展性,我们可以对 Spring容器一次启动中所有bean的初始化的时间 进行监控;可能首先想到的是用AOP,但 aop监控的可能不是太方便, 每个bean的初始化方法除了afterProperties之外,还有其它各自配置的初始化方法, 用 aop方法进行 bean的初始化监控就有点过度了,看过Spring源码的或对Spring内部机制比较熟悉同学可能都知道BeanPostProcessor , 一个bean在初始化的时候,会调用BeanPostProcessor 实现类的前置处理方法和后置处理方法,这两个方法分别每 一个bean的初始化之前和初始化之后进行相关的处理操作,在这里提一下,AOP的动态代理的实现用的是Spring框架中前置处理器进行动态代理的创建,spring中前置处理器的接口如下:
package org.springframework.beans.factory.config;
import org.springframework.beans.BeansException;
public interface BeanPostProcessor {
/**
* Apply this BeanPostProcessor to the given new bean instance before any bean
* initialization callbacks
**/
Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException;
/**
Apply this BeanPostProcessor to the given new bean instance any bean
* initialization callbacks
**/
Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException;
}
有了BeanPostProcessor 扩展接口,就有办法了,我们可以实现一个简单的统计bean初始化时间的BeanPostProcessor 实现类, 并放到我们应用的Spring容器中,代码如下:
package com.tmall.latour.application.performance;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.BeansException;
import org.springframework.beans.factory.config.BeanPostProcessor;
import org.springframework.stereotype.Service;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
/*
* desheng.tds
*/
@Service
public class BeaninitializationPerformanceMonitor implements BeanPostProcessor {
private static Logger logger = LoggerFactory.getLogger(BeaninitializationPerformanceMonitor.class);
private Map<String, Long> staticsMaps = new ConcurrentHashMap<String, Long>();
@Override
public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
staticsMaps.put(beanName, System.currentTimeMillis());
logger.error("id={},class={}", beanName, bean.getClass().getName());
return bean;
}
@Override
public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
if (staticsMaps.get(beanName) != null) {
Long t = System.currentTimeMillis() - staticsMaps.get(beanName);
logger.error("id={},class={},t={}ms", beanName, bean.getClass().getName(), t);
}
return bean;
}
}
加上监控日志配置:
<appender name="ClassPerformanceMonitor_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${loggingRoot}/latour_classPerformanceMonitor.log</file>
<encoding>UTF-8</encoding>
<append>true</append>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${loggingRoot}/latour_classPerformanceMonitor.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>7</maxHistory>
</rollingPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] - %msg%n</pattern>
</layout>
</appender>
<logger name="com.tmall.latour.application.performance.BeaninitializationPerformanceMonitor" level="info" additivity="false">
<appender-ref ref="ClassPerformanceMonitor_LOG"/>
</logger>
为了方便监控 spring 在整个启动过程中的情况,我们还可以加上如下的日志配置
<appender name="SPRING_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${loggingRoot}/spring_info.log</file>
<encoding>UTF-8</encoding>
<append>true</append>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${loggingRoot}/spring_info.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>7</maxHistory>
</rollingPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}][%-5level][%logger{0}] - %msg%n</pattern>
</layout>
</appender>
<!--spring 日志 start-->
<logger name="org.springframework.web.context.support.XmlWebApplicationContext" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.beans.factory.xml.XmlBeanDefinitionReader" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.context.support.PropertySourcesPlaceholderConfigurer" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.beans.factory.config.PropertyPlaceholderConfigurer" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.web.servlet.DispatcherServlet" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.context.support.DefaultLifecycleProcessor" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<logger name="org.springframework.web.context.ContextLoader" level="debug" additivity="false" >
<appender-ref ref="SPRING_LOG" />
</logger>
<!--spring 日志 end-->
监控效果
加上上面这些监控代码之后,我们只需要提交一下本地代码,在aone重新部署一下,观察相关的日志如下,从监控日志中,我们要以看出一些初始化比较耗时的bean,下图示例中:keyStore这个bean初始化消耗6s多,是比较耗时间的
id=keyStore,class=com.taobao.common.keycenter.keystore.KeyStoreImpl,t=6586ms
从启动的监控日志中,我们要看出应用中绝大部分bean的初始化快都是非常快的,只是有些中间件(RocketMQ, 精卫,notify, TDDL, tair, 燎原)的客户端和个别业务client(uic, ic, cargo, honolulu, mtop, IC, KFC 等)启动比较慢, 然后我们可以根据需需要,对这些客户端的bean进行适当的改造,在 预发环境满足条件的,启动的速度可以大大地提高 ,此外我们还可以监控到Spring容器的启动过程:
如何优化启动慢的bean
拿latour 这个应用来说, 发现IcClient, mtop, uic, kfc这几个bean的初始化速度比较度,拿Mtop这个bean来说,原来是配置是这样的:
<bean id="mtopHsfagent" class="com.taobao.mtop.api.agent.MtopAgent" init-method="init">-->
<property name="appName">
<value>latour</value> <!--特别注意,此处要修改成PE或者aone的应用名-->
</property>
</bean>
我们发现这个bean的启动先后不影响其它bean的启动,但这个bean的启动太消耗时间,如于考虑修改成异步初始始,由于mtop这个类没有实现InitializingBean接口,因此可以实现一个Mtop的子类如下:
package com.tmall.latour.application.performance;
import com.taobao.mtop.api.agent.MtopAgent;
import org.springframework.beans.factory.InitializingBean;
/**
* mtop启动加速
* desheng.tds
*/
public class LatourMtopAgent extends MtopAgent implements InitializingBean {
/**
*表示是否是是异步启动
*/
private boolean asyn;
@Override
public void afterPropertiesSet() throws Exception {
if (!asyn) {
this.init();
} else {
new Thread(new LatourMtopAgentRunnable(this)).start();
}
}
private static class LatourMtopAgentRunnable implements Runnable {
private LatourMtopAgent latourMtopAgent;
public LatourMtopAgentRunnable(LatourMtopAgent latourMtopAgent) {
this.latourMtopAgent= latourMtopAgent;
}
@Override
public void run() {
latourMtopAgent.init();
}
}
public void setAsyn(boolean asyn) {
this.asyn = asyn;
}
}
新的bean配置如下
<bean id="mtopHsfagent" class="com.tmall.latour.application.performance.LatourMtopAgent" >
<property name="appName" value="latour"/>
<property name="asyn" value="${asyn}" />
</bean>
再看IcClient这个类,监控发现这个类初始化的时间特别长,30s~50s不等,这个bean的启动也不太影响其它的bean(至少来说在预发环境是这样的),但这个bean的启动优化方案不能参考上面mtop优化方案,因为IcClient这个类实现了InitializingBean接口,可以考虑用代理的方法来解决这个问题,我们也重新写一个类,命名为LatourIcClient,代码如下:
package com.tmall.latour.application.performance;
import com.taobao.item.bootstrap.IcClient;
import com.taobao.item.exception.IcException;
import com.taobao.uic.common.util.ClientInfo;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.InitializingBean;
public class LatourIcClient implements InitializingBean{
private static Logger logger = LoggerFactory.getLogger(LatourIcClient.class);
private IcClient icClient;
private boolean asyn;
public void afterPropertiesSet() throws IcException {
if (!asyn) {
icClient = createIcClientInstance();
icClient.afterPropertiesSet();
} else {
new Thread(new LatourIcRunnable(this)).start();
}
}
private static IcClient createIcClientInstance() {
IcClient icClient = new IcClient();
icClient.setAppName("latour");
icClient.setAllowCustomClientInfo(false);
ClientInfo clientInfo = new ClientInfo();
clientInfo.setAppName("latour");
clientInfo.setEmail("*********");
icClient.setClientInfo(clientInfo);
return icClient;
}
private static class LatourIcRunnable implements Runnable {
private LatourIcClient latourIcClient;
public LatourIcRunnable(LatourIcClient latourIcClient) {
this.latourIcClient = latourIcClient;
}
@Override
public void run() {
try {
latourIcClient.icClient = createIcClientInstance();
latourIcClient.icClient.afterPropertiesSet();
} catch (Exception e) {
logger.error("LatourIcClient init failed", e);
throw new RuntimeException(e);
}
}
}
public void setAsyn(boolean asyn) {
this.asyn = asyn;
}
}
<bean id="icClient" class="com.taobao.item.bootstrap.IcClient">
<property name="appName" value="latour"/>
<property name="clientInfo" ref="clientInfoForUic" />
</bean>
新的bean如下:
<bean id="icClient" class="com.tmall.latour.application.performance.LatourIcClient">
<property name="asyn" value="${asyn}"/>
</bean>
在此特别说明一下,优化Spring bean的初始化时间,方法有多种,但一定要结果具体的bean的情况进行具体分析,一般有继承子类,代理,lazy-init等方法,为了安全起见,asyn这个环境变量,在日常环境和预发环境设置为true,表示慢bean的初始化用异步的方式,在线上最好还是设置成false,表示慢bean的初始化用同步的方式,毕竟大家不经常线上发布应用,不会在乎这多余2min左右的启动时间,但是优化启动时间对开发环境 日常和预发的意义就比较大;
优化效果
由于latour是一个比较老的应用,有部分代码是无用的,可以下线,经过精减代码和针对初始化比较慢的bean进行异步化优化改造,启动速度大提高,优化之前,latour的启动情况如下:
优化后,latour的启动情况如下:
整体启动时间由原来240s减少到110s 左右,应用启动速度整体上提高了近100%