记一次 SpringBoot 启动慢的问题-CSDN博客

本文链接：https://blog.csdn.net/gxy_2016/article/details/145286957

记一次 SpringBoot 启动慢的问题

背景
问题描述
分析处理
为什么这样
- 反向检索
- 问题梳理
复盘
- 处理流程
- 为什么
Reference

背景

最近临时接了一个任务，就从一个旧 springboot 项目 copy 出来，临时写个服务，跑一些数据。
项目的基本配置：

JDK 1.8
spring boot 2.0.6.RELEASE
tomcat 9.0.83
Hibernate 5
org.postgresql.postgresql-42.2.9 版本
Postgresql 14.10

项目功能很简单，就是查一批数据，处理一些逻辑。
时间紧任务重，赶紧噼里啪啦开干。
未曾想简单项目也有“鬼”。

问题描述

匆匆忙忙搞完我的 CURD 代码，再拼装一下，点击启动，趁着空档，接个水，上个厕所。

回来了，浏览器 http://localhost:8080 回车，居然报错了，没有服务？？？

切换到 IDEA，看一下控制台输出日志，嗯？怎么还没显示端口号 server start成功呢？

[2025-01-21 10:59:32,931] restartedMain org.hibernate.annotations.common.reflection.java.JavaReflectionManager 66 INFO HCANN000001: Hibernate Commons Annotations {5.0.1.Final}
[2025-01-21 10:59:32,994] restartedMain com.mchange.v2.log.slf4j.Slf4jMLog $Sl f 4 j M L o gg er$ InfoLogger 212 INFO Initializing c3p0 pool… com.mchange.v2.c3p0.ComboPooledDataSource []
[2025-01-21 10:59:33,276] restartedMain org.hibernate.dialect.Dialect 157 INFO HHH000400: Using dialect: org.hibernate.dialect.PostgreSQL94Dialect

最后一行日志， org.postgresql.Postgresql.Dailet , 好像是 Hibernate 初始化的 SQL 方言。

那就再等一下看看。

好家伙，这一等，足足快5分钟，终于慢悠悠地启动成功。

不应该呀，这么简单的单体 spring boot 项目，连个 PG，处理个数据，要启动5分钟，有没有搞错？

反复重启 2-3次，发现一直卡到那个地方。

以我之前的经验，多半卡在那个 Spring Bean 的初始化上了，而且跟 PG 有关。

上次碰到这个是还是上次呢，依稀记得是 rabbitMQ 初始化，因为网络问题，连接超时后一直连接重试，也是卡了几分钟。

不废话，上工具–照妖镜（Profiler），看看哪里搞鬼。

分析处理

使用 IDEA 自带的 Intellij Profiler，开启路径：
View > Tool > Profiler

main 方法上打断点，启动项目，选中进程，然后在 profiler 中开启监控，断点跳过，让它跑。

等了4-5分钟，关闭监控，关闭服务，开始看看我们抓到了什么。

Flame Graph 火焰图

选中 restartedMain 线程，这个是我们的启动线程，右侧看看火焰图，看哪里耗时多。
注意右上角切换成 Total Time。
在这里插入图片描述

这个栈是真深，我就不截全了。

发现它就是个平顶山，耗时的大头都在最上面。
java.net.SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int)
一下干到 native 代码了，还能看到 windows 平台的动态链接库，微软的Socket库……

有几个关键路径：
hibernate5 buildSessionFactory
org.postgresql.jdbc.PgDatabaseMetaData.getTypeInfo()
org.postgresql.jdbc.TypeInfoCache.getSQLType(String)

Call Tree 调用树

换个视角看看，切换到 Call Tree 菜单，选中 restartedMain 线程。

spring 容器初始化的栈是真滴深，我只抓出最后一部分，时间单位是毫秒。
在这里插入图片描述

PgDatabaseMetaData.getTypeInfo() 执行了 236秒，还没返回，耗时占了整个运行时长的 99.2%，真无语了。

关键词检索

Google 搜索关键词：postgresql jdbc TypeCache.getSQLType blocked on socket read

扒拉扒拉，没啥有价值的信息。

问题相似，但是没有最终的解决掉：

https://postgrespro.com/list/thread-id/2699119

这个也是类似，最后有提示，可能是驱动版本和 pg 版本不对照

https://confluence.atlassian.com/jirakb/connection-problems-to-postgresql-result-in-stuck-threads-in-jira-1047534091.html

PostgreSQL jdbc driver version
PostgreSQL jdbc 驱动程序版本
The socketTimeout connection property was not enforced properly due to a bug in the driver. Version 42.2.15 (2020-08-14) includes a bug fix:
由于驱动程序中存在错误，因此未正确实施 socketTimeout 连接属性。版本 42.2.15 （2020-08-14）修复了一个错误：
● “Make sure socketTimeout is enforced PR 1831, 210b27a6” from the PostgreSQL JDBC Driver change log.
“确保强制实施 socketTimeout PR 1831、210b27a6”，来自 PostgreSQL JDBC 驱动程序更改日志。
Additionally, a bug exists in JDBC versions prior to 42.2.19 where SocketTimeoutException was ignored and thus timeout did not work as expected. Version 42.2.19 (2021-02-18) includes a bug fix:
此外，在 42.2.19 之前的 JDBC 版本中存在一个错误，即忽略 SocketTimeoutException，因此超时无法按预期工作。版本 42.2.19 （2021-02-18）修复了一个错误：
● “properly set cancel socket timeout PR 2044 e551d1a6” from the PostgreSQL JDBC Changelog
“正确设置取消套接字超时 PR 2044e551d1a6”来自 PostgreSQL JDBC 更改日志
Please ensure that version 42.2.19 or later is used to ensure that the socketTimeout connection property works as expected.
请确保使用版本 42.2.19 或更高版本，以确保 socketTimeout 连接属性按预期工作。

得去 github 上搜搜 issues: QueryExecutorImpl.execute block

看了几个 issue，都没有匹配我的问题

尝试解决

根据检索的信息，以及 PG 的版本和驱动的对应关系，优先调整驱动版本。

pogtgresql 14.10 => 驱动 42.6.X +
从 42.2.9 切换到 42.6.1 版本，重新 build，启动

OK了，启动很顺利。

问题解决了，但是莫名其妙的。

为什么这样

反向检索

肯定是 42.2.9 -> 42.6.1 中间有那个版本修复了这个问题。

没有办法的办法，反向分析，去 release 信息里去看看版本发布的 bug fix。

找到 42.2.10 版本发布信息时，发现了一个 PR：

Fix Network Performance of PgDatabaseMetaData.getTypeInfo() method by @dupski in #1668
修复 PgDatabaseMetaData.getTypeInfo() 方法的网络性能 by in #1668

哦吼，这不是跟我们的调用栈很相似吗？

我们看一下，它是修复的那个 issue:

Retrieving system column data types is slow #1342
https://github.com/pgjdbc/pgjdbc/issues/1342
关键词是 Retrieving system column data types is slow , 这可跟我们的检索词一点都不搭边。

但是内容确实很相似，继续查找，PgDatabaseMetaData.getTypeInfo()

N+1 SELECT caused by PgDatabaseMetaData#getTypeInfo() # 1301
https://github.com/pgjdbc/pgjdbc/issues/1301
这个 issue 跟我们的很像， PgDatabaseMetaData.getTypeInfo() 跑了 4分钟左右才返回。

感兴趣的可以深入看一下。