> 原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，非公眾號轉載保留此聲明。 ### 簡介 我們組有一個流量較大的Java服務，每次發代碼時，服務都會有一小波介面超時，之前簡單分析過，發現這些超時的case僅發生在服務剛啟動時，少量請求會耗時好幾秒，但之後又馬上恢復正常。 ### 問題 ...
原創：扣釘日記（微信公眾號ID：codelogs），歡迎分享，非公眾號轉載保留此聲明。
簡介
我們組有一個流量較大的Java服務，每次發代碼時，服務都會有一小波介面超時，之前簡單分析過，發現這些超時的case僅發生在服務剛啟動時，少量請求會耗時好幾秒，但之後又馬上恢復正常。
問題發生
如下，是我們服務的一次上線，可以看到，上線期間(21:10左右)會有一小波499超時。
而從我們全鏈路日誌平臺查看這些超時的調用，會發現外部網路操作(如：rpc調用、查詢資料庫等)耗時不高，所以耗時來源於執行java代碼而非外部調用。
但為啥就剛啟動完成那會比較耗時，之後又正常了呢，有點經驗的話，肯定會想到這裡面估計發生了什麼隱式操作，那Java代碼執行時會有哪些隱式操作可能導致耗時高呢？
我想到瞭如下幾種情況：
- 懶載入操作，如連接池初始化、緩存載入？
經過檢查，發現這些都已在啟動時載入，不會延遲到請求時。
- 發生了GC？
經過檢查，啟動時GC正常，耗時不高。
- JIT即時編譯功能導致？
java代碼預設是解釋執行的，當某些代碼被多次執行後，會被JIT編譯成原生指令執行，執行性能相應提升，但我通過JVM參數-Xint關閉了JIT後，發現問題依然存在，故排除了此原因。
- 執行過程中有鎖？
經過檢查代碼，未發現鎖的存在。
- 操作系統相關隱式操作，上下文切換、缺頁中斷、文件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);
}
}
}
類預載入上線後，後面又進行過多次代碼發佈，發佈過程中幾乎不會再產生超時情況，問題確認已解決。
總結
此次問題的排查過程，還是用到了不少排查技巧的，總結一下：
- 當看起來不應該慢的代碼執行慢時，可以想想有哪些可能的隱式操作存在，此次case的隱式操作就是類載入。
- 當診斷問題沒有頭緒時，可考慮使用arthas的
profile命令來繪製火焰圖，看從火焰圖中能不能找到線索，儘管不會總是有效。 - 當從CPU火焰圖中看不出明顯問題時，可通過對比問題前後的火焰圖來找不同點。
- 理解profile的
-e cpu(預設)與-e wall選項的差異，一般-e cpu診斷高cpu問題，而-e wall診斷高耗時問題，但如果是偶爾慢一下，需要case by case分析，可考慮使用jfr格式保存診斷數據。
