簡介

我們組有一個流量較大的Java服務(wù)，每次發(fā)代碼時，服務(wù)都會有一小波接口超時，之前簡單分析過，發(fā)現(xiàn)這些超時的case僅發(fā)生在服務(wù)剛啟動時，少量請求會耗時好幾秒，但之后又馬上恢復正常。

問題發(fā)生

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

而從我們?nèi)溌啡罩酒脚_查看這些超時的調(diào)用，會發(fā)現(xiàn)外部網(wǎng)絡(luò)操作(如：rpc調(diào)用、查詢數(shù)據(jù)庫等)耗時不高，所以耗時來源于執(zhí)行java代碼而非外部調(diào)用。

但為啥就剛啟動完成那會比較耗時，之后又正常了呢，有點經(jīng)驗的話，肯定會想到這里面估計發(fā)生了什么隱式操作，那Java代碼執(zhí)行時會有哪些隱式操作可能導致耗時高呢？
我想到了如下幾種情況：

• 懶加載操作，如連接池初始化、緩存加載？

經(jīng)過檢查，發(fā)現(xiàn)這些都已在啟動時加載，不會延遲到請求時。

• 發(fā)生了GC？

經(jīng)過檢查，啟動時GC正常，耗時不高。

• JIT即時編譯功能導致？

java代碼默認是解釋執(zhí)行的，當某些代碼被多次執(zhí)行后，會被JIT編譯成原生指令執(zhí)行，執(zhí)行性能相應(yīng)提升，但我通過JVM參數(shù)-Xint關(guān)閉了JIT后，發(fā)現(xiàn)問題依然存在，故排除了此原因。

• 執(zhí)行過程中有鎖？

經(jīng)過檢查代碼，未發(fā)現(xiàn)鎖的存在。

• 操作系統(tǒng)相關(guān)隱式操作，上下文切換、缺頁中斷、文件io慢？

經(jīng)初步檢查，CPU、內(nèi)存、磁盤使用率都正常，這部分深入排查比較費力，且有權(quán)限限制，暫先跳過。

那會是什么原因?qū)е碌模?/p>

問題排查

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

由于超時僅發(fā)生在剛啟動完成后的部分請求，之后又恢復正常，故我計劃在啟動完成后開始收集火焰圖，每次收集10s的火焰圖，收集3次，然后對比前后的火焰圖，看看它們有什么不同，收集腳本如下：

function flamegraph_sample(){
    # 不斷檢測服務(wù)直到它啟動完成
    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個火焰圖如下：

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

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

為此，我計劃使用profile命令的-e wall模式收集剛啟動完成時的調(diào)用棧，并使用jfr格式保存數(shù)據(jù)，其中wall模式適合診斷高耗時問題，而jfr格式數(shù)據(jù)會保存時間戳與線程名稱，適合case by case分析，命令如下：

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

收集到j(luò)fr文件后，使用jmc工具打開，然后我在日志平臺上找到一個慢調(diào)用日志，它顯示http-nio-8080-exec-28線程在21:14:10到21:14:18時間段是一次耗時近8s的慢調(diào)用，所以我用此條件在jmc里過濾出此case的調(diào)用棧數(shù)據(jù)，如下：

可以發(fā)現(xiàn)，確實絕大多數(shù)耗時發(fā)生在類加載上，類加載之所以慢是因為加載類有鎖競爭，而我們接口由于查表較多，確實會觸發(fā)非常多類的加載，所以問題比較明顯。

問題解決

知道原因后，解決起來就簡單了，把類提前加載到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);
        }
    }
}

類預加載上線后，后面又進行過多次代碼發(fā)布，發(fā)布過程中幾乎不會再產(chǎn)生超時情況，問題確認已解決。

總結(jié)

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

• 當看起來不應(yīng)該慢的代碼執(zhí)行慢時，可以想想有哪些可能的隱式操作存在，此次case的隱式操作就是類加載。
• 當診斷問題沒有頭緒時，可考慮使用arthas的profile命令來繪制火焰圖，看從火焰圖中能不能找到線索，盡管不會總是有效。
• 當從CPU火焰圖中看不出明顯問題時，可通過對比問題前后的火焰圖來找不同點。
• 理解profile的-e cpu(默認)與-e wall選項的差異，一般-e cpu診斷高cpu問題，而-e wall診斷高耗時問題，但如果是偶爾慢一下，需要case by case分析，可考慮使用jfr格式保存診斷數(shù)據(jù)。

以上就是Java服務(wù)剛啟動時接口超時排查全過程的詳細內(nèi)容，更多關(guān)于Java服務(wù)啟動接口超時排查的資料請關(guān)注腳本之家其它相關(guān)文章！

最新評論