Spring Boot 项目启动慢排查

背景


打开一个几年前的老项目,发现启动巨慢,同样的代码没动过,当年在渣渣 i5 上运行也只要十几秒,现在升了配置反而要好几分钟。

原始慢启动日志

截图中的项目已经精简了部分内容

问题定位


INFO  RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true

首先注意到这句报错,意思是 RocketMQ 没连上 ,按理说应该没影响,不过以防万一还是本地启动一下 RocketMQ

start mqnamesrv && mqbroker -c ../conf/broker.conf

重启项目发现耗时还是差不多( 相对于总时长来说几秒的误差可以忽略不计 )。

再注意到下面的日志, RocketMQListener 注册成功之前等待了大约 10 秒的时间。

2022-12-19 18:53:21.484 - 42601   [NettyClientSelector_1] INFO  RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
2022-12-19 18:53:32.552 - 53669   [NettyClientSelector_1] INFO  RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
2022-12-19 18:53:32.554 - 53671   [main] INFO  org.apache.rocketmq.spring.support.DefaultRocketMQListenerContainer:243 : running container: DefaultRocketMQListenerContainer{consumerGroup='DEFAULT_GROUP', nameServer='127.0.0.1:9876', topic='DEFAULT_TOPIC', consumeMode=CONCURRENTLY, selectorType=TAG, selectorExpression='*', messageModel=CLUSTERING}
2022-12-19 18:53:32.554 - 53671   [main] INFO  org.apache.rocketmq.spring.autoconfigure.ListenerContainerConfiguration:107 : Register the listener to container, listenerBeanName:myRocketMQListener, containerBeanName:org.apache.rocketmq.spring.support.DefaultRocketMQListenerContainer_1

为了测试方便,之前只保留了一个 RocketMQListener ,其他的都注释掉了,现在放开注释后发现,每个 RocketMQListener 注册成功之前都会等待大约 10 秒。说明这部分的代码是有点问题的,但还不是启动慢的主要原因,继续看日志( 把 RocketMQListener 都先注释掉 ):

2022-12-19 18:52:45.440 - 6557    [main] INFO  com.Application:658 : The following profiles are active: dev
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.springframework.cglib.core.ReflectUtils$1 (file:/H:/maven/org/springframework/spring-core/5.0.12.RELEASE/spring-core-5.0.12.RELEASE.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of org.springframework.cglib.core.ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2022-12-19 18:53:18.903 - 40020   [main] INFO  org.apache.coyote.http11.Http11NioProtocol:180 : Initializing ProtocolHandler ["http-nio-0.0.0.0-3000"]

这部分警告日志的前后间隔了大约 30 秒,说明 Spring 初始化有点慢,但看不到具体的细节,需要在 log4j2 配置中放开一下 Springdebug 日志:

<AsyncLogger name="org.springframework" level="debug"/>

可以看到每个 Bean 实例化都挺快的,唯独下面两个部分卡了一会儿:

2022-12-19 19:15:29.185 - 7538    [main] INFO  org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'rocketmq-org.apache.rocketmq.spring.autoconfigure.RocketMQProperties' of type [org.apache.rocketmq.spring.autoconfigure.RocketMQProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:15:39.070 - 17423   [main] INFO  org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'defaultMQProducer' of type [org.apache.rocketmq.client.producer.DefaultMQProducer] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:15:39.120 - 17473   [main] INFO  org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'jacksonObjectMapper' of type [com.fasterxml.jackson.databind.ObjectMapper] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:16:03.671 - 42024   [main] INFO  org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'rocketMQTemplate' of type [org.apache.rocketmq.spring.core.RocketMQTemplate] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

这里耗时大约 30 秒,和前面可以对上。

由于项目目前用不上 RocketMQ ,可以把 RocketMQAutoConfiguration 配置先屏蔽掉看下:

@SpringBootApplication(exclude = { RocketMQAutoConfiguration.class })
public class Application {

  // ...

  @Bean
  public RocketMQTemplate rocketMQTemplate() {
    // 造一个假的 rocketMQTemplate 避免项目报错
    RocketMQTemplate rocketMQTemplate = new RocketMQTemplate();
    rocketMQTemplate.setProducer(new DefaultMQProducer("groupName"));
    return rocketMQTemplate;
  }
}

重启项目只需要 20 多秒了,虽然还是慢但至少能接受,可以确定是 RocketMQ 的问题了。而且所有依赖的中间件都是本地部署的,基本可以忽略网络问题了( 后面打脸 ),实在想不通为什么会慢。

解决方法


拿着 rocketMQTemplate 启动慢 的关键词去搜问题简直是大海捞针,不过运气好找到了一篇文章《 RocketMQ 很慢?引出了一个未解之谜 》, 里面指出了 NetworkInterface.getNetworkInterfaces 这个 JDK 方法的耗时问题 ,本地测试了一下果然如此:

public class NetworkInterfaceTest {

  public static void main(String[] args) throws SocketException {
    long start = System.currentTimeMillis();
    Enumeration<NetworkInterface> enumeration = NetworkInterface.getNetworkInterfaces();
    long end = System.currentTimeMillis();

    ArrayList<NetworkInterface> result = new ArrayList<>();
    while (enumeration.hasMoreElements()) {
      result.add(enumeration.nextElement());
    }
    System.out.printf(
      "NetworkInterface.getNetworkInterfaces() use %d ms, result size: %d%n",
      end - start,
      result.size()
    );
  }
}

getNetworkInterfaces 测试

真凶果然是它,一次调用耗时将近 6 秒,不加限制多调用几次就能爆炸了。可以看一下这个方法的返回结果是什么:

getNetworkInterfaces 返回结果

光看名字就能联想到 控制面板\网络和 Internet\网络连接 中的 网络适配器 ,基本能对上:

网络适配器

之所以有这么多的设备是因为之前安装 Genymotion 模拟器的时候 VirtualBox 给安装上的,因为没遇到过其他问题也就没在意,没想到却导致了 getNetworkInterfaces 调用变慢的问题。而 getNetworkInterfaces 方法底层调用的是 getAll 这个 native 方法,所以代码层面基本没得改了,目前 唯一解决方法 就是 把没用的网络适配器都禁用掉 ,最后耗时只要 600 毫秒了( 不同的网卡耗时程度不同 ),这种程度基本能接受了。

getNetworkInterfaces 测试 - 禁用后

把测试代码放 VMware 构建的纯净系统环境下又测了一遍,发现最初调用只要 31 毫秒,这种程度的耗时才是正常的,难怪以前都没发现这个问题,而安装 Genymotion 后耗时果然就显著增加了。

回到项目还原代码验证一下,启动时间果然恢复到正常的 8 秒了。

问题解决后正常启动日志

问题复盘


这个问题得到解决得亏有人用 RocketMQ 的时候遇到类似的问题,不然就只能不了了之了。不过和别人说 getNetworkInterfaces 方法调用很慢大概率会被人当傻子,比如有人在 RocketMQ 仓库提过 类似问题 直接被无视了。

xxxProducerxxxConsumer 都继承 ClientConfig ,因此每实例化一个就会调用一次 getNetworkInterfaces

继续查资料看有没有方法可以定位耗时的代码块,在《 SpringBoot 服务启动慢排查思路 》一文中看到了一张 JProfiler 的方法调用树截图,里面清楚标红了耗时比较长的方法,但是文章中没有具体的操作步骤,只能自己研究下。

后来才发现在 JProfiler 帮助文档 中关于这部分内容已经介绍的很详细了。

操作步骤:

  • 下载安装 JProfiler

  • IDEA 中用 JProfiler 图标启动项目

  • JProfilerbin 目录启动主程序 jprofiler.exe

  • Attach > 选择 背景色标绿 的项目进程 > 开始

    配置项一路确定就好了。

    许可证密钥 错误会导致 启动报错 的,需要选择 评估 ( 试用 10 天 )。

    修改系统时间后重启 JProfiler 可以继续试用。( 用完了再把系统时间还原回去 )

    JProfiler> ERROR: Invalid license key. Aborting.
    JProfiler> Killing process
    

    清除已填写的注册码:

    cd /d "%USERPROFILE%/.jprofiler13" && del jprofiler_config.xml
    
  • CPU 视图 > 调用树 > 开始记录

    这一步手速要快一点,不然可能会错过一些重要的调用过程。当然也可以在 会话启动 的配置窗口中设置 初始化记录分析 以自动开始记录。

    JProfiler 会话启动
  • 等待项目启动完成

    JProfiler 分析调用树

调用树结果是有了,但坑爹的是展开之后报红的线索就断了,基本是 1% 以内的正常方法调用,完全看不到里层的慢方法。点击工具栏中的 分析 按钮,将结果转为火焰图看下:

JProfiler 查看火焰图

可以看到两侧缺失了一大片的内容,说明有一些方法被隐藏了没记录在内,这时回到调用树,注意到每个方法前面的图标都不太一样,正好工具栏有一个 显示图例 的按钮,点击查看内容:

JProfiler 树图例

这说明部分方法被过滤了,最后在 会话设置 > 调用树过滤器 > 定义过滤器 中发现默认配置把一堆第三方库都过滤了:

JProfiler 定义过滤器 - 默认

这里只需要添加被分析的包( 注意顺序,具体配置规则见 官方文档 )即可:

java. // 看情况是否要加
javax.
org.apache.
JProfiler 定义过滤器 - 自定义

重启项目重新开始分析就能得到想要的结果了:

JProfiler 分析调用树 - 最终结果

查看火焰图效果更直观,可以看到大部分时间都花费在 getNetworkInterfaces 上了( 8 次调用共耗时 37 秒 ),也证实了前面问题定位没有错。

JProfiler 查看火焰图 - 最终结果

其他相关问题


解决完这个问题忽然想到前段时间碰到的另一个问题:用到 JSP 的项目从 JDK1.8 切换到 JDK11 后,第一次访问页面很慢,并有警告日志:

WARN 6244 --- [nio-8080-exec-1] o.a.c.util.SessionIdGeneratorBase        : Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [6,337] milliseconds.

SecureRandom 的耗时问题 以前在 Docker 容器 中运行 Tomcat 时遇到过,但和这次显然不是一回事,定位到打日志的代码:

createSecureRandom

发现耗时的地方在 SecureRandom.nextInt() ,只是肉眼去看代码不好去分析更底层的调用栈,还好刚学会了 JProfiler ,分析结果一目了然,这个问题同样也是 getNetworkInterfaces 在捣鬼。

JProfiler 分析调用树 - SecureRandom

至于为什么 JDK1.8 没问题,由于调用栈发生了变化一时也查不出原因,我猜测可能是其他地方( 可能无法被分析器拦截到 )提前触发了 SecureRandom.SeederHolderstatic 代码初始化。比如 debug 模式 运行项目时打断点发现 sun.management.Agent.startAgent() 中就间接调用了 SecureRandom


转载请注明出处: https://github.com/anyesu/blog/issues/44

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 144,247评论 1 305
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 61,830评论 1 258
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 95,531评论 0 214
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 41,345评论 0 183
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 49,160评论 1 260
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 38,936评论 1 178
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 30,538评论 2 275
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,291评论 0 168
  • 想象着我的养父在大火中拼命挣扎,窒息,最后皮肤化为焦炭。我心中就已经是抑制不住地欢快,这就叫做以其人之道,还治其人...
    爱写小说的胖达阅读 29,162评论 6 237
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 32,654评论 0 214
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,401评论 2 217
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 30,747评论 1 232
  • 白月光回国,霸总把我这个替身辞退。还一脸阴沉的警告我。[不要出现在思思面前, 不然我有一百种方法让你生不如死。]我...
    爱写小说的胖达阅读 24,297评论 1 33
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,206评论 2 213
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 31,670评论 3 213
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,661评论 0 9
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,089评论 0 169
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 33,677评论 2 233
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 33,819评论 2 237

推荐阅读更多精彩内容