一次服务启动慢问题排查

随着时间推移，参与开发的人员越来越多，项目代码也会越来越复杂，需要我们有意识的定期对代码进行优化，有问题及时解决，避免技术债务越积越多。
这不本人就遇到一个服务启动慢的问题，印象中服务启动是比较快的，一般也就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