簡介

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

問題發(fā)生

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

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

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

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

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

2. 發(fā)生了GC？

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

3. JIT即時(shí)編譯功能導(dǎo)致？

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

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

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

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

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

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

問題排查

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

由于超時(shí)僅發(fā)生在剛啟動完成后的部分請求，之后又恢復(fù)正常，故我計(jì)劃在啟動完成后開始收集火焰圖，每次收集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個(gè)火焰圖如下：

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

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

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

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

問題解決

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

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

總結(jié)

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

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