一次服務啟動慢問題排查

隨著時間推移，參與開發的人員越來越多，專案程式碼也會越來越複雜，需要我們有意識的定期對程式碼進行優化，有問題及時解決，避免技術債務越積越多。
這不本人就遇到一個服務啟動慢的問題，印象中服務啟動是比較快的，一般也就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