我们线上的业务 jar 包基本上普遍比较庞大,动不动一个 jar 包上百 M,启动时间在分钟级,拖慢了我们在故障时快速扩容的响应。于是做了一些分析,看看 Java 程序启动慢到底慢在哪里,如何去优化,目前的效果是大部分大型应用启动时间可以缩短 30%~50%
主要有下面这些内容
- 修改 async-profiler 源码,只抓取启动阶段 main 线程的 wall 时间火焰图(:white_check_mark:)
- 重新实现 JarIndex(:white_check_mark:)
- 结合 JarIndex 重新自定义类加载器,启动提速 30%+(:white_check_mark:)
- SpringBean 加载耗时 timeline 可视化分析(:white_check_mark:)
- SpringBean 的可视化依赖分析(:white_check_mark:)
- 基于依赖拓扑的 SpringBean 的异步加载(:x:)
无观测不优化
秉承着无观测不优化的想法,首先我们要知道启动慢到底慢在了哪里。我之前分享过很多次关于火焰图的使用,结果很多人遇到问题就开始考虑火焰图,但是一个启动慢其实是一个时序问题,不是一个 hot CPU 热点问题。很多时候慢,不一定是 cpu 占用过高,很有可能是等锁、等 IO 或者傻傻的 sleep。
在 Linux 中有一个杀手级的工具 bootchart 来分析 linux 内核启动的问题,它把启动过程中所有的 IO、CPU 占用情况都做了详细的划分,我们可以很清楚的看到各个时间段,时间耗在了哪里,基于这个 chart,你就可以看看哪些过程可以延后处理、异步处理等。
在 Java 中,暂时没有类似的工具,但是又想知道时间到底耗在了哪里要怎么做呢,至少大概知道耗在了什么地方。在生成热点调用火焰图的时候,我们通过 arthas 的几个简单的命令就可以生成,它底层用的是 async-profiler 这个开源项目,它的作者 apangin 做过一系列关于 jvm profiling 相关的分享,感兴趣的同学可以去看看。
async-profiler 底层原理简介
async-profiler 是一个非常强大的工具,使用 jvmti 技术来实现。它的 NB 之处在于它利用了 libjvm.so 中 JVM 内部的 API AsyncGetCallTrace
来获取 Java 函数堆栈,精简后的伪代码如下:
static bool vm_init(JavaVM *vm) { std::cout << "vm_init" << std::endl; // 从 libjvm.so 中获取 AsyncGetCallTrace 的函数指针句柄 void *libjvm = dlopen("libjvm.so", RTLD_LAZY); _asyncGetCallTrace = (AsyncGetCallTrace) dlsym(libjvm, "AsyncGetCallTrace"); } // 事件回调 void recordSample(void *ucontext, uint64_t counter, jint event_type, Event *event) { std::cout << "Profiler::recordSample: " << std::endl; ASGCT_CallFrame frames[maxFramesToCapture]; ASGCT_CallTrace trace; trace.frames = frames; trace.env = getJNIEnv(g_jvm); // 调用 AsyncGetCallTrace 获取堆栈 _asyncGetCallTrace(&trace, maxFramesToCapture, ucontext); }
你可能要说获取个堆栈还需要搞这么复杂,jstack 等工具不是实现的很好了吗?其实不然。
jstack 等工具获取函数堆栈需要 jvm 进入到 safepoint,对于采样非常频繁的场景,会严重的影响 jvm 的性能,具体的原理不是本次内容的重点这里先不展开。
async-profiler 除了可以生成热点调用的火焰图,它还提供了 Wall-clock profiling
的功能,这个功能其实就是固定时间采样所有的线程(不管线程当前是 Running、Sleeping 还是 Blocked),它在文档中也提到了,这种方式的 profiling 适合用来分析应用的启动过程,我们姑且用这个不太精确的方式来粗略测量启动阶段耗时在了哪些函数里。
但是这个工具会抓取所有的线程的堆栈,按这样的方式抓取的 wall-clock 火焰图没法看,不信你看。
就算你找到了 main 线程,在函数耗时算占比的时候也不太方便,我们关心的其实只是 main 线程(也就是加载 jar 包,执行 spring 初始化的线程),于是我做了一些简单的修改,让 async-profiler 只取抓取 main 线程的堆栈。
重新编译运行
java -agentpath:/path/to/libasyncProfiler.so=start,event=wall,interval=1ms,threads,file=profile.html -jar xxx.jar
这样生成的火焰图就清爽多了,这样就知道时间耗在了什么函数上。
接下来就是分析这个 wall-clock 的火焰图,点开几个调用栈仔细分析,发现很多时间花费在类和资源文件查找和加载(挺失望的,java 连这部分都做不好)
继续分析代码看看类加载在做什么。
Java 垃圾般实现的类查找加载
Java 的类加载不出意外最终都走到了 java.net.URLClassLoader#findClass 这里。
这里的 ucp 指的是 URLClassPath,也就是 classpath 路径的集合。