设为首页 加入收藏

TOP

一次服务启动慢问题排查
2023-07-26 08:17:30 】 浏览:59
Tags:

随着时间推移,参与开发的人员越来越多,项目代码也会越来越复杂,需要我们有意识的定期对代码进行优化,有问题及时解决,避免技术债务越积越多。
这不本人就遇到一个服务启动慢的问题,印象中服务启动是比较快的,一般也就20几秒,但这次开发一个需求发现服务启动要接近1分钟,这对本地开发调试,测试同学测试都是非常不方便的,影响工作效率。

启动服务后观察日志,发现在最后一行这里卡了好久,但没有更有帮助的日志信息打印正在做什么。从图看起来像是xxl job的问题,但这是很早就引入了的,以前启动并不会慢,通过打断点也可以看出xxl job的初始化并没有阻塞。

image

一般服务启动慢原因主要有:
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参数配置。

image

服务启动后分析结果如下:

image

可以看到dslContext花费了23秒多,占用了接近一半的时间了。那这个是不是就是在上面xxl job日志后卡住的原因呢?我们看如下的详细过程,发现确实如此。

image

解决问题:
从图可以看出问题就是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做升级,根据经验这就是问题所在了。

image

上github也可以看到我们使用这个版本的sharding的jooq确实会导致服务启动慢,参见issues,官方下一个小版本就修复这个问题。

解决方式也很简单,升级一些sharding-jdbc即可,通过上面的分析知道也可以排除jooq依赖,@SpringBootApplication(exclude = {JooqAutoConfiguration.class})。
解决后重启服务观察到,jooq的初始化没有了,服务启动快了20多秒。

image

欢迎关注我的github:https://github.com/jmilktea/jtea

】【打印繁体】【投稿】【收藏】 【推荐】【举报】【评论】 【关闭】 【返回顶部
上一篇Java后端01(初识servlet) 下一篇反射 p3 类加载

最新文章

热门文章

Hot 文章

Python

C 语言

C++基础

大数据基础

linux编程基础

C/C++面试题目