SpringBoot 服务启动慢排查思路

最新推荐文章于 2024-07-14 14:09:24 发布

犬小哈

最新推荐文章于 2024-07-14 14:09:24 发布

阅读量228

点赞数

原文链接：https://mp.weixin.qq.com/s?__biz=MzU4MDUyMDQyNQ==&mid=2247537874&idx=2&sn=573de0ea638cc1a6d054d44ca36f5887&chksm=fceee76549f7962f5afb15fd38b1b86db06c901ea9258bdaa1bc798f8ab57d17e38bc4481ea1&scene=126&sessionid=0

版权

来源：blog.csdn.net/lkx444368875/article/details/127268108

👉 欢迎加入小哈的星球，你将获得: 专属的项目实战 / Java 学习路线 / 一对一提问 / 学习打卡 / 每月赠书

新项目:仿小红书(微服务架构)正在更新中... 。全栈前后端分离博客项目 2.0 版本完结啦， 演示链接：http://116.62.199.48/ 。全程手摸手，后端 + 前端全栈开发，从 0 到 1 讲解每个功能点开发步骤，1v1 答疑，直到项目上线。目前已更新了287小节，累计45w+字，讲解图：2008张，还在持续爆肝中.. 后续还会上新更多项目，目标是将Java领域典型的项目都整一波，如秒杀系统, 在线商城, IM即时通讯，Spring Cloud Alibaba 等等，戳我加入学习，已有1600+小伙伴加入(早鸟价超低)

Jprofile - CPU检测
线程等待

一个其他团队的比较老的dubbo服务，spring的版本在3.2.x范围，用的还是spring那一套。

由于这个服务比较核心，而且集成的组件比较多：rabbit、dubbo、es、kafka、zk、redis、cas等等一系列组件，然后开发的痛点就是本地启动时间太慢了，常常耗时接近10分钟、机器配置差点夸张到10+。抱着好奇的心理开始这一次排查之旅。

❝

启动耗时 : Artifact xxxx:war exploded: Deploy took 730,358 milliseconds

优化成果: Artifact xxxx:war exploded: Deploy took 95,078 milliseconds

❞

由于老服务启动日志偏少，索性开始之前使用过的JProfiles来作为本次的分析工具，它可以实时侦测所有代码的运行耗时。对一些启动慢链路追踪有非常好的帮助。

Jprofile - CPU检测

基于Jprofile的使用文章

❝

https://blog.csdn.net/lkx444368875/article/details/108799142

❞

通过JProfile检测，发现了一个比较耗时的点：就是

图片

这个类的作用是:

// 通过反射判断实例是否存在
public static boolean isPresent(String className, ClassLoader classLoader) {
    try {
        forName(className, classLoader);
        return true;
    } catch (Throwable var3) {
        return false;
    }
}

/**
* The class name of AnnotatedElementUtils that is introduced since Spring Framework 4
*/
public static final String ANNOTATED_ELEMENT_UTILS_CLASS_NAME = "org.springframework.core.annotation.AnnotatedElementUtils";

// 往上追踪的话是查找AnnotatedElementUtils是否存在
ClassUtils.isPresent(ANNOTATED_ELEMENT_UTILS_CLASS_NAME, classLoader)

很显然这个过程就是nacos会判断AnnotatedElementUtils是否存在，通过注释我们可以了解到AnnotatedElementUtils这个类是Spring 4的版本，而这个服务还只是3.2.x，如果这个类没有相当于在扫描bean容器查看nacos相关注解的时候，所有类都会经过classLoader判断一遍，这些基本上都是无效判断，类多了耗时严重。原本想着升级Spring版本，发现牵一发动全身~那既然版本没跟上那么就直接关闭该功能呗，

通过继续往上追踪com.alibaba.spring.util.AnnotationUtils#getAnnotationAttributes到这个类时有一个tryMergedAnnotation属性的判断:

public static AnnotationAttributes getAnnotationAttributes(AnnotatedElement annotatedElement,
            Class<? extends Annotation> annotationType,
            PropertyResolver propertyResolver,
            boolean classValuesAsString,
            boolean nestedAnnotationsAsMap,
            boolean ignoreDefaultValue,
            boolean tryMergedAnnotation,
            String... ignoreAttributeNames) {

    AnnotationAttributes attributes = null;

    if (tryMergedAnnotation) {
        attributes = tryGetMergedAnnotationAttributes(annotatedElement, annotationType, propertyResolver,
                classValuesAsString, nestedAnnotationsAsMap, ignoreDefaultValue, ignoreAttributeNames);
    }

    if (attributes == null) {
        attributes = getAnnotationAttributes(annotatedElement, annotationType, propertyResolver,
                classValuesAsString, nestedAnnotationsAsMap, ignoreDefaultValue, ignoreAttributeNames);
    }

    return attributes;
}

这个说明只有这个属性为true的时候，才会扫描加载AnnotatedElementUtils，嗯，我们可以自己定义去覆盖原本nacos自动注册的类，然后坑此坑次的在配置文件加上了。

<bean id="annotationNacosInjectedBeanPostProcessor"
    class="com.alibaba.nacos.spring.beans.factory.annotation.AnnotationNacosInjectedBeanPostProcessor">
  <property name="tryMergedAnnotation" value="false"/>
 </bean>

<bean id="nacosValueAnnotationBeanPostProcessor"
    class="com.alibaba.nacos.spring.context.annotation.config.NacosValueAnnotationBeanPostProcessor">
  <property name="tryMergedAnnotation" value="false"/>
</bean>

嗯，这个问题解决了，开始启动。

效果还是有的，时间减少了40%吧，但还是远远不够，继续观察。

❝

Artifact xxxx:war exploded: Deploy took 462,016 milliseconds

❞

线程等待

通过日志发现经过一段时间后，不打印了。

[2022-09-28 17:15:56.913][ WARN][][][SimpleAsyncTaskExecutor-1][o.s.a.r.l.SimpleMessageListenerContainer|1168]:Consumer raised exception, processing can restart if the connection factory supports it. Exception summary: org.springframework.amqp.AmqpConnectException: java.net.ConnectException: Connection timed out: connect

连接超时，这个一看是rabbitMQ的，我想应该也不会阻塞主线程吧？

这个时候我在想：主线程在干啥呀！？

图片

"RMI TCP Connection(3)-127.0.0.1@1830" daemon prio=5 tid=0x14 nid=NA waiting
  java.lang.Thread.State: WAITING
   at sun.misc.Unsafe.park(Unsafe.java:-1)
   at java.util.concurrent.locks.LockSupport.<obsolete>(LockSupport.java:-1)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
   at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
   at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.getStartupException(SimpleMessageListenerContainer.java:992)
   at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doStart(SimpleMessageListenerContainer.java:666)
   - locked <0x3314> (a java.lang.Object)
   at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.start(AbstractMessageListenerContainer.java:458)
   at org.springframework.context.support.DefaultLifecycleProcessor.doStart(DefaultLifecycleProcessor.java:167)
   at org.springframework.context.support.DefaultLifecycleProcessor.access$200(DefaultLifecycleProcessor.java:51)
   at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.start(DefaultLifecycleProcessor.java:339)
   at org.springframework.context.support.DefaultLifecycleProcessor.startBeans(DefaultLifecycleProcessor.java:143)
   at org.springframework.context.support.DefaultLifecycleProcessor.onRefresh(DefaultLifecycleProcessor.java:108)
   at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:945)
   at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:482)

发现线程居然阻塞等待了！！！

通过观察线程栈找到SimpleMessageListenerContainer这个类的getStartupException方法，看到了令我绝望的代码

private final CountDownLatch start = new CountDownLatch(1);

public FatalListenerStartupException getStartupException() throws TimeoutException, InterruptedException {
    start.await(60000L, TimeUnit.MILLISECONDS);
    return this.startupException;
}

public void run() {
 SimpleMessageListenerContainer.this.redeclareElementsIfNecessary();
    this.consumer.start();
    this.start.countDown();

    // 省略
    restart(this.consumer);
}

它其实是有唤醒的操作的，但是由于启动不成功，唤醒不了，又触发重试，继续等待。但我没想明白的是这个东西怎么是在主线程做的，也不确定是不是包版本太低的原因。

Rabbit连不上这个其实也是有原因的，因为我们这边的本地的都是连的测试环境的，nacos的测试环境配置是阿里云内网的地址，导致本地肯定是连不上的，所以我找了个公网地址试了一下，发现果然有用。

❝

优化成果: Artifact xxxx:war exploded: Deploy took 95,078 milliseconds

❞

其实还发现了一些其他阻塞，不过都是属于连接方面的，比如zk、数据库等等，目前这个古老的项目1分半也属于偏正常范围吧，主要还是组件太多，代码也多。

好了，本次排查到此为止。排查的手段和方案可以给大家提供一种思路~

👉 欢迎加入小哈的星球，你将获得: 专属的项目实战 / Java 学习路线 / 一对一提问 / 学习打卡 / 每月赠书

新项目:仿小红书(微服务架构)正在更新中... 。全栈前后端分离博客项目 2.0 版本完结啦， 演示链接：http://116.62.199.48/ 。全程手摸手，后端 + 前端全栈开发，从 0 到 1 讲解每个功能点开发步骤，1v1 答疑，直到项目上线。目前已更新了287小节，累计45w+字，讲解图：2008张，还在持续爆肝中.. 后续还会上新更多项目，目标是将Java领域典型的项目都整一波，如秒杀系统, 在线商城, IM即时通讯，Spring Cloud Alibaba 等等，戳我加入学习，已有1600+小伙伴加入(早鸟价超低)

1. 我的私密学习小圈子~
2. 为了方便开发，我实现了一个Redis 工具集
3. 面试官：线程池提交一个任务占多大内存？
4. 离谱！CPU狂飙900%，这怎么处理？

最近面试BAT，整理一份面试资料《Java面试BATJ通关手册》，覆盖了Java核心技术、JVM、Java并发、SSM、微服务、数据库、数据结构等等。
获取方式：点“在看”，关注公众号并回复 Java 领取，更多内容陆续奉上。

PS：因公众号平台更改了推送规则，如果不想错过内容，记得读完点一下“在看”，加个“星标”，这样每次新文章推送才会第一时间出现在你的订阅列表里。
点“在看”支持小哈呀，谢谢啦

犬小哈

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
SpringBoot 服务启动慢排查思路

来源：blog.csdn.net/lkx444368875/article/details/127268108???? 欢迎加入小哈的星球，你将获得:专属的项目实战 / Java 学习路线 /一对一提问 / 学习打卡 / 每月赠书新项目:仿小红书(微服务架构)正在更新中... 。全栈前后端分离博客项目 2.0 版本完结啦，演示链接：http://116.62.199.48/。全程手摸手，后端...
复制链接

扫一扫