簡(jiǎn)介
我們組有一個(gè)流量較大的Java服務(wù)，每次發(fā)代碼時(shí)狐胎，服務(wù)都會(huì)有一小波接口超時(shí)鸭栖，之前簡(jiǎn)單分析過(guò)，發(fā)現(xiàn)這些超時(shí)的case僅發(fā)生在服務(wù)剛啟動(dòng)時(shí)握巢，少量請(qǐng)求會(huì)耗時(shí)好幾秒晕鹊，但之后又馬上恢復(fù)正常。
問(wèn)題發(fā)生
如下镜粤，是我們服務(wù)的一次上線捏题，可以看到，上線期間(21:10左右)會(huì)有一小波499超時(shí)肉渴。
而從我們?nèi)溌啡罩酒脚_(tái)查看這些超時(shí)的調(diào)用公荧，會(huì)發(fā)現(xiàn)外部網(wǎng)絡(luò)操作(如：rpc調(diào)用、查詢數(shù)據(jù)庫(kù)等)耗時(shí)不高同规，所以耗時(shí)來(lái)源于執(zhí)行java代碼而非外部調(diào)用循狰。
但為啥就剛啟動(dòng)完成那會(huì)比較耗時(shí)，之后又正常了呢券勺，有點(diǎn)經(jīng)驗(yàn)的話绪钥，肯定會(huì)想到這里面估計(jì)發(fā)生了什么隱式操作，那Java代碼執(zhí)行時(shí)會(huì)有哪些隱式操作可能導(dǎo)致耗時(shí)高呢关炼？
我想到了如下幾種情況：
- 懶加載操作程腹，如連接池初始化、緩存加載儒拂？
經(jīng)過(guò)檢查寸潦，發(fā)現(xiàn)這些都已在啟動(dòng)時(shí)加載，不會(huì)延遲到請(qǐng)求時(shí)社痛。
- 發(fā)生了GC见转？
經(jīng)過(guò)檢查，啟動(dòng)時(shí)GC正常蒜哀，耗時(shí)不高斩箫。
- JIT即時(shí)編譯功能導(dǎo)致？
java代碼默認(rèn)是解釋執(zhí)行的撵儿，當(dāng)某些代碼被多次執(zhí)行后乘客，會(huì)被JIT編譯成原生指令執(zhí)行，執(zhí)行性能相應(yīng)提升淀歇，但我通過(guò)JVM參數(shù)-Xint關(guān)閉了JIT后寨典，發(fā)現(xiàn)問(wèn)題依然存在，故排除了此原因房匆。
- 執(zhí)行過(guò)程中有鎖？
經(jīng)過(guò)檢查代碼，未發(fā)現(xiàn)鎖的存在浴鸿。
- 操作系統(tǒng)相關(guān)隱式操作井氢，上下文切換、缺頁(yè)中斷岳链、文件io慢花竞？
經(jīng)初步檢查，CPU掸哑、內(nèi)存约急、磁盤使用率都正常，這部分深入排查比較費(fèi)力苗分，且有權(quán)限限制厌蔽，暫先跳過(guò)。
那會(huì)是什么原因?qū)е碌模?/p>
問(wèn)題排查
暫時(shí)沒啥頭緒摔癣，我打算先用arthas的profile命令奴饮，收集一些CPU火焰圖看看。
由于超時(shí)僅發(fā)生在剛啟動(dòng)完成后的部分請(qǐng)求择浊，之后又恢復(fù)正常戴卜，故我計(jì)劃在啟動(dòng)完成后開始收集火焰圖，每次收集10s的火焰圖琢岩，收集3次投剥，然后對(duì)比前后的火焰圖，看看它們有什么不同担孔，收集腳本如下：
function flamegraph_sample(){
# 不斷檢測(cè)服務(wù)直到它啟動(dòng)完成
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è)火焰圖如下：
乍一看江锨，火焰圖中沒有明顯的瓶頸點(diǎn)，但經(jīng)過(guò)仔細(xì)查看攒磨，在第一張火焰圖中搜索ClassLoader泳桦，可以搜到不少類加載操作(紅色部分)，而第二張則基本沒有娩缰！
難道是類加載導(dǎo)致的灸撰？目前我有80%信心懷疑就是它導(dǎo)致的，但類加載有那么慢拼坎？
為此浮毯，我計(jì)劃使用profile命令的-e wall模式收集剛啟動(dòng)完成時(shí)的調(diào)用棧，并使用jfr格式保存數(shù)據(jù)泰鸡，其中wall模式適合診斷高耗時(shí)問(wèn)題债蓝，而jfr格式數(shù)據(jù)會(huì)保存時(shí)間戳與線程名稱，適合case by case分析盛龄，命令如下：
profiler start -e wall --file /tmp/result.jfr
收集到j(luò)fr文件后饰迹，使用jmc工具打開芳誓，然后我在日志平臺(tái)上找到一個(gè)慢調(diào)用日志，它顯示http-nio-8080-exec-28線程在21:14:10到21:14:18時(shí)間段是一次耗時(shí)近8s的慢調(diào)用啊鸭，所以我用此條件在jmc里過(guò)濾出此case的調(diào)用棧數(shù)據(jù)锹淌，如下：
可以發(fā)現(xiàn)，確實(shí)絕大多數(shù)耗時(shí)發(fā)生在類加載上赠制，類加載之所以慢是因?yàn)榧虞d類有鎖競(jìng)爭(zhēng)赂摆，而我們接口由于查表較多，確實(shí)會(huì)觸發(fā)非常多類的加載钟些，所以問(wèn)題比較明顯烟号。
問(wèn)題解決
知道原因后，解決起來(lái)就簡(jiǎn)單了政恍，把類提前加載到JVM即可汪拥，為了簡(jiǎn)單，我直接使用了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)行過(guò)多次代碼發(fā)布，發(fā)布過(guò)程中幾乎不會(huì)再產(chǎn)生超時(shí)情況鹤树，問(wèn)題確認(rèn)已解決铣焊。
總結(jié)
此次問(wèn)題的排查過(guò)程，還是用到了不少排查技巧的罕伯，總結(jié)一下：
- 當(dāng)看起來(lái)不應(yīng)該慢的代碼執(zhí)行慢時(shí)曲伊，可以想想有哪些可能的隱式操作存在，此次case的隱式操作就是類加載追他。
- 當(dāng)診斷問(wèn)題沒有頭緒時(shí)坟募，可考慮使用arthas的
profile命令來(lái)繪制火焰圖，看從火焰圖中能不能找到線索邑狸，盡管不會(huì)總是有效懈糯。 - 當(dāng)從CPU火焰圖中看不出明顯問(wèn)題時(shí)，可通過(guò)對(duì)比問(wèn)題前后的火焰圖來(lái)找不同點(diǎn)单雾。
- 理解profile的
-e cpu(默認(rèn))與-e wall選項(xiàng)的差異赚哗，一般-e cpu診斷高cpu問(wèn)題，而-e wall診斷高耗時(shí)問(wèn)題硅堆，但如果是偶爾慢一下屿储，需要case by case分析，可考慮使用jfr格式保存診斷數(shù)據(jù)渐逃。
