记一次 SpringBoot 启动慢的问题

背景

最近临时接了一个任务，就从一个旧 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$Slf4jMLogger$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分钟左右才返回。

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

问题梳理

试着梳理一下，不一定对。

写个 3分钟速食版试着解释一下这个问题：

Hibernate sessionFactory 初始化的时候，会从 JDBC 驱动 的DatabaseMetaData 中提取类型信息。
我是用的是PG库， 驱动对应的是 PgDatabaseMetaData.getTypeInfo() 。

在 PG 中除了基本的列类型外，表也是一种复合类型，包括：视图，函数，序列等。
getTypeInfo 的规范说 get all of the types，所以查所有类型，包括表，视图，函数，序列，类型等元信息。

这个检索动作很慢，驱动程序首先执行 SQL 查询以获取可用类型，然后再循环地为每种类型运行SQL查询，这个地方存在严重的网络性能，会在启动阶段卡死，查询很久。

那么PgDatabaseMetaData.getTypeInfo()查询所有类型信息究竟要返回哪些信息，需要PG驱动实现的时候进行取舍。

42.2.6 版本 PgDatabaseMetaData.getTypeInfo 已经移除了 table类型（包括 表 视图 函数 序列），套用一句维护者的话：

Well I think removing tables from the typecache would help. I can’t imagine a database with 200k types

https://github.com/pgjdbc/pgjdbc/pull/1302
开眼了吧，业务的水也很深的好吧。

42.2.10 版本 优化了 PgDatabaseMetaData.getTypeInfo 的网络性能。
https://github.com/pgjdbc/pgjdbc/pull/1668
优化了类型信息的获取

从 42.2.9 到 42.6.2 版本更新中涉及到 PgDatabaseMetaData.getTypeInfo 只有这两个，所以42.2.10 版本应该能解决我的问题。
PS: 我重新用 42.2.10 版本启动了，6秒完成启动，这个版本也有效

但 PG 跨大版本升级后，会存在一些改动，尤其是元数据的部分，为了避免潜在的坑，还是使用跟 14.10 匹配的版本 42.6.1 吧。

所以使用驱动的时候一定要确定好 DB 的版本与驱动是否匹配。

复盘

处理流程

想起了一句名言：问题的关键是要找到关键的问题。

那么我们是怎么找到和定位这个关键的问题的呢？
启动速度慢，用性能分析工具，对启动耗时进行准确的定位。

定位问题之后，我们是如何处理的？
我是没法直接搞定这个问题，只能查看方法调用栈，快速提取关键词进行检索。

搜索引擎解决问题了吗，有其他方式吗？
搜索引擎没直接解决我们的问题，但是给我们提供了一些思路。
如果无法检索到的话，就需要回到源头，去项目的 github 社区，搜索 issue。

我们的关键词可能无法匹配到 issue，那怎么办？
去 release 发布信息中去查看，可能这个问题已经修复了。

又总结了一个经典处理套路：
有问题的话，升个版试试，说不定新版本已经解决这个问题了。

重启和升版总有一个适合你。

为什么

这个问题本来觉得很简单，只是驱动版本不匹配的问题。
但是为了总结整理，反而挖到了不少知识盲区。

凡是多问个为什么，比别人多想一步，总会有意想不到的收货。
不要老是在水面游泳，偶尔也要扎个猛子，下潜一下，看看不一样的风景。

看了大佬们的 issue 讨论，好像自己也参与了一样，感觉真不错。

Enjoy Code, Enjoy Life.

Reference

N+1 SELECT caused by PgDatabaseMetaData#getTypeInfo()
https://github.com/pgjdbc/pgjdbc/pull/1302
Retrieving system column data types is slow
https://github.com/pgjdbc/pgjdbc/pull/1668