一個接口的性能問題定位和分析過程
本文來自網易雲社區
通過性能測試平臺的介紹和一些培訓,我們已經可以進行性能測試了,但是性能測試了除了測試執行之外,性能問題定位和分析也是至關重要的一個環節,下面我們以一個典型的例子,開始一個接口的性能問題定位和分析過程。
接口最初的性能
·TPS:9.6
·MRT:2067ms
·RT90 值:2537ms
·應用服務器 CPU 使用率:30%
我們期望接口的性能TPS 大於150,平均響應時間小於300ms,該接口顯然不滿足預期。該接口的特點是:響應時間過長,TPS 上不去,並且應用服務器的資源使用未有瓶頸點,那麽瓶頸點可能在其他服務器上。出於經驗,我們可以想到可能是sql 語句沒索引導致的,那麽通過Oracle 自帶的AWR 工具來驗證下,是不是sql 語句的問題。
第一次性能問題定位和分析
AWR 是Oracle 自帶的性能統計工具,可以在性能測試開始之前和結束之後分別創建一次快照,然後統計該時間段內的數據庫性能情況。AWR 工具會生成HTML 格式的報告,該報告包含非常豐富的統計信息,包含資源使用情況、sql 執行情況、內存使用情況等,我們只需要關註sql 的執行時間就可以發現問題,如下圖:
從標紅中我們可以看到這條sql 的執行時間接近1s,對於單條sql 的執行時間來說,簡單的sql 執行時間應該小於10ms,略微復雜的sql 我們也期望其執行時間可以小於100ms。基於這個標準,我們可以認為該sql 語句確實存在問題。遇到這種慢查詢sql,可以首先排查索引原因,去數據庫中查看對應表的索引字段,確實是索引未建的問題。
找到問題,我們增加索引後,性能變為:
·TPS:71
·MRT:768ms
·RT90 值:946ms
·應用服務器 CPU 使用率:90% 以上
該性能結果依然沒有達到我們的期望值,且從結果看來,問題應該在應用服務這一層。
第二次性能問題定位和分析
遇到CPU 使用率高,且TPS 比較低的情況,我們可以通過jstack 查看內存堆棧信息,排查下比較耗費CPU 的接口、是否存在鎖等待等問題。
通過這兩部分數據,我們可以看到存在Java IO 的鎖競爭,進一步通過堆棧信息,可以找到應用層代碼去排查問題原因。
這個問題的原因是在高頻調用的一個接口中存在System.out.println 的日誌輸出。而System.out 的輸出是同步輸出接口,當有大量的這種類型的輸出時,一定會出現鎖等待現象。
去掉這種類型的輸出語句後:
·TPS:81
·MRT:594ms
·RT90 值:696ms
·應用服務器 CPU 使用率:90% 以上
優化之後的性能依然沒有達到我們的要求。
第三次性能問題定位和分析
目前這個接口的問題依然是CPU 使用率高,且TPS 上不去。我們使用JProfiler 工具更進一步的分析消耗CPU 的接口是哪些。
通過JProfiler 的CPU profiler 功能,我們定位到消耗CPU 高的方法為checkLoginIn(),該接口的功能是判斷用戶是否登錄,應該是個比較簡單且常用的接口。把這個問題拋給開發後,通過接口的調用信息,開發定位到原因是在請求的cookie 當中沒有給定jsessionid,導致每次都認為是一個新的請求,每次都會生成新的用戶數據信息放入到數據庫中,邏輯操作變復雜。
增加jsessionid 後:
·TPS:111
·MRT:445ms
·RT90 值:533ms
·應用服務器 CPU 使用率:90% 以上
依然未達到我們的要求,我們繼續用JProfiler 查看消耗CPU 的接口,是否還存在問題。這次我們看到,一個請求forward 到jsp 頁面,會調用40 多次session.getAttribute。
循環調用問題,開發優化後的性能:
·TPS:165
·MRT:300ms
·RT90 值:373ms
·應用服務器 CPU 使用率:90% 以上
該結果基本滿足我們的性能要求,JProfiler 繼續查看消耗CPU 的接口時,發現接口的特點是邏輯實現略微復雜,執行內容過多,沒有再找到什麽可以優化的地方了。
總結
一個小小的接口,花費了大量的時間定位性能差的原因,雖然耗時很久,但是效果還可以。這個接口的一系列定位過程,基本上用到了很多我們常用的定位方法,希望可以給大家後續性能問題定位帶來啟發。
網易雲新用戶大禮包:https://www.163yun.com/gift
本文來自網易實踐者社區,經作者侯本文授權發布。
一個接口的性能問題定位和分析過程