一次服务启动慢问题排查
随着时间推移,参与开发的人员越来越多,项目代码也会越来越复杂,需要我们有意识的定期对代码进行优化,有问题及时解决,避免技术债务越积越多。
这不本人就遇到一个服务启动慢的问题,印象中服务启动是比较快的,一般也就20几秒,但这次开发一个需求发现服务启动要接近1分钟,这对本地开发调试,测试同学测试都是非常不方便的,影响工作效率。
启动服务后观察日志,发现在最后一行这里卡了好久,但没有更有帮助的日志信息打印正在做什么。从图看起来像是xxl job的问题,但这是很早就引入了的,以前启动并不会慢,通过打断点也可以看出xxl job的初始化并没有阻塞。
一般服务启动慢原因主要有:
1.程序太大了,加载的bean非常多,默认情况下spring没有使用异步加载,如果bean太多可能导致启动慢。
2.在启动时做一些业务初始化,如使用@PostConstruct,在方法内进行接口调用,数据库查询等IO操作,可能导致服务启动慢。
3.在启动时做一些框架初始化,如使用数据库orm框架,通常需要加载数据库元信息,如果数据库表过多,加载时间长,可能导致服务启动慢。
那要怎么排查这个问题呢?
恰好在github上看到一个工具就可以发现问题所在,spring-startup-analyzer,可以分析spring应用启动过程。
spring-startup-analyzer
使用步骤非常简单:
1.下载最新的包,放到用户目录下,注意最好放到用户目录下,否则可能会有问题。
2.添加启动命令
-Dspring-startup-analyzer.app.health.check.endpoints=http://localhost:8020/actuator/health -javaagent:C:/Users/huangyb1/spring-startup-analyzer/lib/spring-profiler-agent.jar
-Dspring-startup-analyzer.app.health.check.endpoints 是健康检查的url,当这个接口返回200就表示服务启动完成了。
-javaagent 配置为上面下载的包路径
3.启动观察有如下日志表示正常,8065断开可以查看分析报告,可以通过-Dspring-startup-analyzer.admin.http.server.port参数配置。
服务启动后分析结果如下:
可以看到dslContext花费了23秒多,占用了接近一半的时间了。那这个是不是就是在上面xxl job日志后卡住的原因呢?我们看如下的详细过程,发现确实如此。
解决问题:
从图可以看出问题就是dlsContext这个加载慢导致,并且它是一个org.jooq.impl.DefaultDSLContext,由org.jooq.impl.DefaultConfiguration导入。
jooq是什么?jOOQ 从您的数据库生成 Java 代码,并允许您通过其流畅的 API 构建类型安全的 SQL 查询。
它可以实现将java代码翻译成sql语句,如:
create.select(AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME, count())
.from(AUTHOR)
.join(BOOK).on(AUTHOR.ID.equal(BOOK.AUTHOR_ID))
.where(BOOK.LANGUAGE.eq("DE"))
.and(BOOK.PUBLISHED.gt(date("2008-01-01")))
.groupBy(AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME)
.having(count().gt(5))
.orderBy(AUTHOR.LAST_NAME.asc().nullsFirst())
.limit(2)
.offset(1)
将被翻译成
SELECT AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME, COUNT(*)
FROM AUTHOR
JOIN BOOK ON AUTHOR.ID = BOOK.AUTHOR_ID
WHERE BOOK.LANGUAGE = 'DE'
AND BOOK.PUBLISHED > DATE '2008-01-01'
GROUP BY AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME
HAVING COUNT(*) > 5
ORDER BY AUTHOR.LAST_NAME ASC NULLS FIRST
LIMIT 2
OFFSET 1
说实话,本人不太喜欢这种书写方式,这种方式看起来并不直观,还没法直接拿这条sql语句出来执行,这种方式比较适合一些sql语句很简单的场景。
我们的项目使用的是mybatis plus,也没有用到jooq,那它是怎么来的呢?通过maven dependency analyzer可以看出,它是由sharding-jdbc带入的,前段时间刚好有同学对sharding-jdbc做升级,根据经验这就是问题所在了。
上github也可以看到我们使用这个版本的sharding的jooq确实会导致服务启动慢,参见issues,官方下一个小版本就修复这个问题。
解决方式也很简单,升级一些sharding-jdbc即可,通过上面的分析知道也可以排除jooq依赖,@SpringBootApplication(exclude = {JooqAutoConfiguration.class})。
解决后重启服务观察到,jooq的初始化没有了,服务启动快了20多秒。
欢迎关注我的github:https://github.com/jmilktea/jtea