技術文章 » Java服務剛啟動時，一小波介面超時排查全過程

Java服務剛啟動時，一小波介面超時排查全過程

2023-07-24 06:01:10

原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，非公眾號轉載保留此宣告。

簡介

我們組有一個流量較大的Java服務，每次發程式碼時，服務都會有一小波介面超時，之前簡單分析過，發現這些超時的case僅發生在服務剛啟動時，少量請求會耗時好幾秒，但之後又馬上恢復正常。

問題發生

如下，是我們服務的一次上線，可以看到，上線期間(21:10左右)會有一小波499超時。

而從我們全鏈路紀錄檔平臺檢視這些超時的呼叫，會發現外部網路操作(如：rpc呼叫、查詢資料庫等)耗時不高，所以耗時來源於執行java程式碼而非外部呼叫。

但為啥就剛啟動完成那會比較耗時，之後又正常了呢，有點經驗的話，肯定會想到這裡面估計發生了什麼隱式操作，那Java程式碼執行時會有哪些隱式操作可能導致耗時高呢？
我想到了如下幾種情況：

  1. 懶載入操作，如連線池初始化、快取載入？

經過檢查，發現這些都已在啟動時載入，不會延遲到請求時。

  1. 發生了GC？

經過檢查，啟動時GC正常，耗時不高。

  1. JIT即時編譯功能導致？

java程式碼預設是解釋執行的，當某些程式碼被多次執行後，會被JIT編譯成原生指令執行，執行效能相應提升，但我通過JVM引數-Xint關閉了JIT後，發現問題依然存在，故排除了此原因。

  1. 執行過程中有鎖？

經過檢查程式碼，未發現鎖的存在。

  1. 作業系統相關隱式操作，上下文切換、缺頁中斷、檔案io慢？

經初步檢查，CPU、記憶體、磁碟使用率都正常，這部分深入排查比較費力，且有許可權限制，暫先跳過。

那會是什麼原因導致的？

問題排查

暫時沒啥頭緒，我打算先用arthas的profile命令，收集一些CPU火焰圖看看。

由於超時僅發生在剛啟動完成後的部分請求，之後又恢復正常，故我計劃在啟動完成後開始收集火焰圖，每次收集10s的火焰圖，收集3次，然後對比前後的火焰圖，看看它們有什麼不同，收集指令碼如下：

function flamegraph_sample(){
    # 不斷檢測服務直到它啟動完成
    while sleep 1; do curl -sS --connect-timeout 3 -m3 http://127.0.0.1:8080/health | grep ok && break; done
    pid=`pgrep -n java`
    for i in {1..3}; do
        java -jar arthas-boot.jar -c "profiler start --alluser" "$pid";
        sleep 10s;
        java -jar arthas-boot.jar -c "profiler stop --file /tmp/flamegraph_cpu_%t.html " "$pid";
    done
    java -jar arthas-boot.jar -c "stop" "$pid";
}

生成的前2個火焰圖如下：


乍一看，火焰圖中沒有明顯的瓶頸點，但經過仔細檢視，在第一張火焰圖中搜尋ClassLoader，可以搜到不少類載入操作(紅色部分)，而第二張則基本沒有！

難道是類載入導致的？目前我有80%信心懷疑就是它導致的，但類載入有那麼慢？

為此，我計劃使用profile命令的-e wall模式收集剛啟動完成時的呼叫棧，並使用jfr格式儲存資料，其中wall模式適合診斷高耗時問題，而jfr格式資料會儲存時間戳與執行緒名稱，適合case by case分析，命令如下：

profiler start -e wall --file /tmp/result.jfr

收集到jfr檔案後，使用jmc工具開啟，然後我在紀錄檔平臺上找到一個慢呼叫紀錄檔，它顯示http-nio-8080-exec-28執行緒在21:14:10到21:14:18時間段是一次耗時近8s的慢呼叫，所以我用此條件在jmc裡過濾出此case的呼叫棧資料，如下：

可以發現，確實絕大多數耗時發生在類載入上，類載入之所以慢是因為載入類有鎖競爭，而我們介面由於查表較多，確實會觸發非常多類的載入，所以問題比較明顯。

問題解決

知道原因後，解決起來就簡單了，把類提前載入到JVM即可，為了簡單，我直接使用了spring中的工具方法，如下：

private static final String[] CLASS_PREFIX_ARR = new String[] {
                "org.apache", "com.thoughtworks", "io.netty", "com.google", "io.grpc",
                "com.alibaba", "org.springframework", "cn.hutool", "com.fasterxml", "org.hibernate", 
                "io.opencensus", "org.redisson", "io.micrometer", "io.prometheus",
        };

PathMatchingResourcePatternResolver resolver = new PathMatchingResourcePatternResolver();
for (String classPrefix : CLASS_PREFIX_ARR) {
    Resource[] resources;
    try {
        resources = resolver.getResources(
                "classpath*:" + StringUtils.replaceChars(classPrefix, '.', '/') + "/**/*.class");
    } catch (IOException e) {
        ExceptionUtils.rethrow(e);
        return;
    }
    for (Resource resource : resources) {
        String className = null;
        try (InputStream is = resource.getInputStream()) {
            ClassReader cr = new ClassReader(is);
            className = StringUtils.replaceChars(cr.getClassName(), '/', '.');
            Class<?> clz = Class.forName(className);
            log.info("preLoadClass success: " + className + ", classLoader: " + clz.getClassLoader());
        } catch (Throwable e) { 
            log.warn("preLoadClass failed: " + className);
        }
    }
}

類預載入上線後，後面又進行過多次程式碼釋出，釋出過程中幾乎不會再產生超時情況，問題確認已解決。

總結

此次問題的排查過程，還是用到了不少排查技巧的，總結一下：

  1. 當看起來不應該慢的程式碼執行慢時，可以想想有哪些可能的隱式操作存在，此次case的隱式操作就是類載入。
  2. 當診斷問題沒有頭緒時，可考慮使用arthas的profile命令來繪製火焰圖，看從火焰圖中能不能找到線索，儘管不會總是有效。
  3. 當從CPU火焰圖中看不出明顯問題時，可通過對比問題前後的火焰圖來找不同點。
  4. 理解profile的-e cpu(預設)與-e wall選項的差異，一般-e cpu診斷高cpu問題，而-e wall診斷高耗時問題，但如果是偶爾慢一下，需要case by case分析，可考慮使用jfr格式儲存診斷資料。