記一次線上接口請(qǐng)求慢問題分析

IT那活兒發(fā)布于2023-01-11 13:20 / 1018人閱讀

最近發(fā)現(xiàn)線上系統(tǒng)有個(gè)頁(yè)面訪問非常緩慢，頁(yè)面打開需要20S左右，抽空優(yōu)化了一下，順便記錄一下分析過程。

首先在慢頁(yè)面打開F12，查看訪問慢的請(qǐng)求如下圖，請(qǐng)求地址為：/modelManage/overviewPage/getDrillDownList，目前的接口請(qǐng)求時(shí)間為17.6S。

通常來(lái)說(shuō)，當(dāng)我們發(fā)現(xiàn)應(yīng)用的某個(gè)接口響應(yīng)比較慢，這時(shí)候想要找到代碼中耗時(shí)的部分，比較容易想到的是在接口鏈路的IO操作上下游打印時(shí)間日志，再根據(jù)幾個(gè)時(shí)間點(diǎn)的日志算出耗時(shí)長(zhǎng)的IO操作。

使用這種方式，加日志需要發(fā)布，既繁瑣又低效。這里就用阿里巴巴開源的 Java 診斷工具 Arthas來(lái)分析下，除了分析耗時(shí)，還可以打印調(diào)用棧、方法入?yún)⒓胺祷兀惣虞d情況，線程池狀態(tài)，系統(tǒng)參數(shù)等。其實(shí)現(xiàn)原理是解析JVM在操作系統(tǒng)中的文件，大部分操作是只讀的，對(duì)服務(wù)進(jìn)程沒有侵入性。

首先，啟動(dòng)arthas。

在出現(xiàn)的列表中選擇要跟蹤的服務(wù)進(jìn)程，看到如下界面說(shuō)明attach成功。

使用sc命令找到待分析的Controller類完整的路徑和名稱。根據(jù)請(qǐng)求地址/modelManage/overviewPage匹配到對(duì)應(yīng)Controller。

使用sm命令查詢類的方法信息，根據(jù)請(qǐng)求名getDrillDownList匹配到Controller具體方法。

拿到Controller類地址和方法名后，通過trace命令查看整個(gè)調(diào)用鏈路上的調(diào)用時(shí)間，觀察到方法內(nèi)調(diào)用service方法占用了大部分時(shí)間。

繼續(xù)trace該service方法的調(diào)用鏈路，觀察到mapper部分占用了大部分耗時(shí)。

由于mapper部分是對(duì)數(shù)據(jù)庫(kù)的操作，于是懷疑sql性能有問題，找研發(fā)拿到該sql語(yǔ)句。

將該語(yǔ)句直接放到pl/sql執(zhí)行，用時(shí)8.9S，確認(rèn)是sql執(zhí)行慢，由于涉及分頁(yè)需要查詢count(*)總條數(shù)，所以該語(yǔ)句執(zhí)行了2次，時(shí)間剛好耗時(shí)18S左右，問題確定。

簡(jiǎn)單分析下該sql，結(jié)構(gòu)并不復(fù)雜，只針對(duì)單表進(jìn)行查詢，表數(shù)據(jù)量有830多萬(wàn)。

作為開發(fā)人員，先簡(jiǎn)單利用PL/SQL Developer的執(zhí)行計(jì)劃評(píng)估SQL語(yǔ)句的性能。這里看到的執(zhí)行計(jì)劃，只是SQL運(yùn)行前可能的執(zhí)行方式，實(shí)際運(yùn)行時(shí)可能因?yàn)檐浻布h(huán)境的不同而有所改變，而且cost高的執(zhí)行計(jì)劃，不一定在實(shí)際運(yùn)行起來(lái)，速度就一定差，我們這里只做一個(gè)參考。這里觀察到該sql的where條件走了全表掃描，占用了大部分耗費(fèi)時(shí)間。