下载源代码建网站,石家庄平台公司,app搭建要多少钱,ppt设计理念记一次 SpringBoot 启动慢的问题 背景问题描述分析处理Flame Graph 火焰图Call Tree 调用树关键词检索尝试解决 为什么这样反向检索问题梳理 复盘处理流程为什么 Reference 背景
最近临时接了一个任务#xff0c;就从一个旧 springboot 项目 copy 出来#xff0c;临时写个服… 记一次 SpringBoot 启动慢的问题 背景问题描述分析处理Flame Graph 火焰图Call Tree 调用树关键词检索尝试解决 为什么这样反向检索问题梳理 复盘处理流程为什么 Reference 背景
最近临时接了一个任务就从一个旧 springboot 项目 copy 出来临时写个服务跑一些数据。 项目的基本配置
JDK 1.8spring boot 2.0.6.RELEASEtomcat 9.0.83Hibernate 5org.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 S l f 4 j M L o g g e r Slf4jMLogger Slf4jMLoggerInfoLogger 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()
N1 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
N1 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
