[TOC]
0x0 背景
目前我们有个项目的代码，每次启动，时间需要 250秒 之久
每次重启，都要漫长的等待，十分痛苦
大家本地调试，也是苦不堪言
这次腾出时间来，专项治理，取得一些效果，把心得分享一下
0x1 工具
俗话说的好 工欲善其事必先利其器
肯定需要先找一个工具来帮我们来分析一下启动过程到底为啥这么慢
业界常见的有 JProfiler
这次无意间发现了一个也不错的 VTune
是CPU厂商 Intel的产品，一听就感觉有点靠谱，毕竟是搞CPU的， (#.#)
1.1 VTune配置
如果是 Spring Boot项目，写一个脚本就行，如下：
java -jar xxx.jar
如果是 war 形式的，放在 tomcat 容器里运行的，直接运行 catalina 脚本是不行的，因为进程发生了切换，脚本是 call 了 java
工具捕获不到
我的方法就是修改 catalina 脚本，把 启动语句 echo 出来
echo
所以实际的启动脚本命令为（仅供参考，以实际为准）
"C:\Program Files\Java\jdk1.8.0_181\bin\java.exe" -Djava.util.logging.config.file="D:\003-tool\054-tomcat\apache-tomcat-8.5.56\conf\logging.properties" -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Dignore.endorsed.dirs="" -classpath "D:\003-tool\054-tomcat\apache-tomcat-8.5.56\bin\bootstrap.jar;D:\003-tool\054-tomcat\apache-tomcat-8.5.56\bin\tomcat-juli.jar" -Dcatalina.base="D:\003-tool\054-tomcat\apache-tomcat-8.5.56" -Dcatalina.home="D:\003-tool\054-tomcat\apache-tomcat-8.5.56" -Djava.io.tmpdir="D:\003-tool\054-tomcat\apache-tomcat-8.5.56\temp" org.apache.catalina.startup.Bootstrap start
1.2 分析
等待漫长的启动结束之后，结束监听，开始分析
vtune
进入 Bottom-up ，可以看到时间之和根本对不上，但是呢，也有排名，将就用吧（最后证明，虽然时间之和对不上，但是真的好用）
先看第一个
func@0x711796f0
第一个
可以看到有个 alibaba 啥的，是因为我们用了 RocketMQ 的 sdk
再看第二个
NtWaitForSingleObject
第二个
完全看不懂，跳过
再看第三个
Java_java_io_FileInputStream_readBytes
第三个
可以看到起点是 spring 的 bean 注册，有点戏
且出现了好多 cglib 的调用
再看第四个
select
第四个
看栈的话，貌似是NIO的，可以跳过
再看第五个
java::io::DataInputStream::readUTF
第五个
看到 spring bean cglib weaver 看样子是 spring aop 对 bean 进行代码织入
再看第六个
jbyte_disjoint_arraycopy
图就不放了，和第五个基本一样
再看第七个
java::io::DataInputStream::readUnsignedShort
图就不放了，和第五个基本一样
再看第八个
JVM_MonitorWait
第八个
和第二个一样，完全看不懂
再看第九个
Java_java_io_FileInputStream_available0
图就不放了，和第五个基本一样
到此发现了一点点端倪，前9个，除了看不懂的和NIO的，其它都是 和 cglib aspectj 有关的
且我们知道 cglib 是 spring aop 的一种实现，通过代码织入的方式来实现的动态代理，比较消耗CPU资源
所以我们可以开始 大胆假设、小心求证
我假设就是 aop 使用了 cglib 导致的
0x2 求证
既然我这样假设，那我把 aop 关了试试，对比一下启动时间
于是把 注解 @EnableAspectJAutoProxy 注释掉，看看时间
经过多次反复重启，发现启动时间 降到了 24秒 左右
bingo ！ 找到了，罪魁祸首就是 aop 的 LTW (加载期代码织入)
0x3 优化
既然找到方向了，那么下一步就要开始着手优化
所以，需要先了解一下 aop 相关知识
3.1 aop
spring aop 有两种实现，如果这个 bean 是对接口的实现，那么就是用的 jdk 动态代理
如果不是，就使用 cglib 在加载期间，进行字节码动态修改，也就是代码织入， 也称之为 LTW (load time weaver)
既然加载期间，代码织入比较费时间，那么换成 编译期间织入 CTW ，这个时间不久降到0，完全节省了么，直接达到 24秒的水平
但是，我们项目的切面代码用到了 比较多的 spring bean，而且切了很多的方法，
如果用 CTW， 那么每个方法都要使用 工具类去 IOC 容器里拿 bean， 总感觉有点怪怪的
所以我就先不考虑这个方案（如果大家有更好的 idea，欢迎指出）
3.2 LTW
排除了CTW， 那么方向就只能选择 LTW了
看到了一个回答 Spring AOP slow startup time
思路就是优化什么匹配过程，那么我们就来看看切面是怎么去匹配bean的
3.3 aop增强过程
aop.png
文字总结一下整体耗时
假设 pointcut 表达式是 @annotation 的
假设有
- 5个
pointcut - 有
100个bean - 平均每个
bean有20个方法 - 平均每个方法
1个注解
那么匹配次数就是
5 * 100 *20 *1 = 10,000 1万次
3.4 bean 数量
规则已经清楚了，那么我们的项目到底是个啥情况呢？
首先想看下我们的工程最终到底有多少个bean
搜到了唯一的一篇 博客
提供了思路，我们的项目有个类实现了 接口 ApplicationListener<ContextRefreshedEvent>, ApplicationContextAware
拿到了 ApplicationContext applicationContext
可以直接打印
LOGGER.info("spring beans count {}", this.applicationContext.getBeanDefinitionCount());
最后得知，有928,算作 920吧
3.5 次数
我们有 11个 @annotation 的切面（其它切面不怎么耗时，暂时不统计）
假设方法数量平均为 20，注解数量平均为 1
那么次数就是
11 * 920 * 20 * 1 = 202,400 20万次
3.6 减少切面个数
依次看了一下切面，有些注解已经不用了，可以删掉
有些注解，可以通过其它方式实现，可以删掉
3.7 优化表达式写法
最后我们还剩下3个 @annotation 的切面
经过再次分析，发现都集中在某些包下面， 回想 3.3 的流程图可以知道，如果在表达式里加一些对类的判断，不符合的bean 判断起来就很快，完全不用遍历方法，再遍历注解
3.7.1 单文件
如果发现注解只会出现在一个文件里
那么可以把注解从之前的 @Pointcut("@annotation(com.xxx.api.annotation.XXX)")
变成 @Pointcut("within(com.xxx.service) && @annotation(com.xxx.api.annotation.XXX)")
3.7.2 多文件但同包
如果发现注解出现在多个文件里，但是都是同一个包，层级也一样
那么可以把注解从之前的 @Pointcut("@annotation(com.xxx.api.annotation.XXX)")
变成 @Pointcut("within(com.xxx.service.*) && @annotation(com.xxx.api.annotation.XXX)")
3.7.3 多文件但子孙包
如果发现注解出现在多个文件里，但是都是同一个顶级包，层级不一样
那么可以把注解从之前的 @Pointcut("@annotation(com.xxx.api.annotation.XXX)")
变成 @Pointcut("within(com.xxx.service..*) && @annotation(com.xxx.api.annotation.XXX)")
3.7.4 混合
来个混合的给大家参考下
@Pointcut(" (within(com.xxx.service.b.*) || within(com.xxx.service.a..*) )&& @annotation(com.xxx.api.annotation.XXX)")
类可能出现在 包 com.xxx.service.b下（不包含子包）
也可能包含在 包com.xxx.service.a 直接包和子孙包下
验收
最后，优化完成，启动时间为 40秒 左右
可喜可贺，时间从 250秒 下降到了 40秒
时间
参考
使用性能分析工具定位Spring Boot启动慢问题
ioc流程1
ioc流程2
Spring AOP slow startup time
spring bean数量
aspectj 介绍
网友评论