性能優化案例(2019-案例78)-接口性能耗時問題分析


在某項目的第一輪性能測試的中,發現某協議響應時間很長,通過javamethod監控相關接口的調用耗時的時候監控結果如下:

onMessage是該協議的總入口,可以看到該協議平均耗時為352.11ms,觀察其他耗時方法可以看到updateUserForeignId耗時307.75ms

那么可以認為該方法的響應時間慢是該協議的最主要性能瓶頸,這時候我們應該看看該方法究竟做了哪些操作導致響應時間過長:

從監控中可以看到userStorage.updateUserForeignId方法耗時122.86ms,userStorage.updateForeignIdPegging方法耗時71.33ms

這兩個方法有成為了SessionProcessHelper.updateUserForeignId方法的主要耗時點,基於對代碼的熟悉程度xxxStroge方法都是一些數據庫的操作,

那么現在可以初步的認為數據庫的相關操作可能是問題的根源所在,為了清楚的展示問題,我們先選擇一個邏輯較簡單的方法分析一下,從上面的方法監控里可以看到updateSession方法耗時34.88ms,查看該方法代碼:

可以看到方法只是有一個簡單的dao層的操作,通過查看dao層方法可知該方法僅僅是一個update操作,按常理來說這樣的操作需要三十多毫秒的耗時,顯然是偏長了,既然如此,

我們繼續求根溯源利用哨兵的mqlcolletor來驗證一下該方法底層的sql操作究竟耗時多少毫秒。此處省略通過dao層方法查找sql語句的過程,直接來看結果:

從這里可以看到底層sql響應時間是1.62ms,而dao層方法耗時高達34.88ms這里顯然有問題的,這里我們首先需要排查一下壓測機,數據庫的各資源指標是否到達瓶頸(在之前的性能測試中發現過類似的問題最后發現是數據庫機器的磁盤util接近100%

該機器性能較差導致出現該問題,后期更換數據庫機器解決了問題),通過檢查這些指標可以發現cpu,內存,網絡,磁盤各項指標均保持在正常水平。

問題到這里,貌似沒有什么進展了,這時候就到了jstack登場了。在Java應用的性能測試中,很多性能問題可以通過觀察線程堆棧來發現,Jstack是JVM自帶dump線程堆棧的工具,很輕量易用,並且執行時不會對性能造成很大的影響。

靈活的使用jstack可以發現很多隱秘的性能問題,是定位問題不可多得的好幫手。我們來jstack一下,查看在測試執行的過程中,各線程所做的操作和線程狀態,可以看到以下狀態:

在所有的24個線程中,多執行幾次jstack可以發現大約有十個左右的線程處於waitting狀態,該狀態表明該線程正在執行obj.wait()方法,放棄了 Monitor,進入 “Wait Set”隊列,為什么阻塞住呢,繼續往下看堆棧信息,

可以看到該線程正在做borrowobject操作,可以大概看到這里是一個數據庫連接池的相關操作,具體到究竟是干什么的可以查看一些數據庫連接池的資料:dbcp源碼解讀與對象池原理剖析     https://blog.csdn.net/suixinm/article/details/41761019

簡單的說一下,數據庫連接的使用過程:創建一個池對象工廠, 將該工廠注入到對象池中, 當要取池對象, 調用borrowObject, 當要歸還池對象時, 調用returnObject, 銷毀池對象調用clear(), 如果要連池對象工廠也一起銷毀, 則調用close()。

從這里可以很明顯的看到該線程waitting的原因是沒有獲取到連接池里的連接對象,那么很容易就可以想象的到導致該問題的原因是數據庫連接池比夠用導致的,於是將連接池的大小從10修改到了50,繼續執行一輪測試得到了以下結果:

可以看到updateSession方法從34.88ms下降到20.13ms,雖然耗時下降了14ms,但是距離sql耗時的1.64ms仍然有差距,沿着剛剛的思路,我們繼續jstack一下,看看當前的線程狀態又是如何:

在24個線程中平均下來會有十個左右的blocked狀態,繼續往下閱讀可以發現,該線程是blocked在了log4j.Category.callAppenders上,顯然可以發現這是個log4j的問題,那究竟為何會阻塞在這里呢,

查看資料可以找到callAppenders的源碼(具體的log4j相關資料可以看這里:Log4j 1.x版引發線程blocked死鎖問題):https://www.iteye.com/blog/zl378837964-2373591

/** 
     Call the appenders in the hierrachy starting at 
     this.  If no appenders could be found, emit a 
     warning. 
 
     
This method calls all the appenders inherited from the 
     hierarchy circumventing any evaluation of whether to log or not 
     to log the particular log request. 
 
     @param event the event to log.   
*/  
  public void callAppenders(LoggingEvent event) {  
    int writes = 0;  
  
    for(Category c = this; c != null; c=c.parent) {  
      // Protected against simultaneous call to addAppender, removeAppender,...  
      synchronized(c) {  
    if(c.aai != null) {  
      writes += c.aai.appendLoopOnAppenders(event);  
    }  
    if(!c.additive) {  
      break;  
    }  
      }  
    }  
  
    if(writes == 0) {  
      repository.emitNoAppenderWarning(this);  
    }  
  }

我們從上面可以看出在該方法中有個synchronized同步鎖,同步鎖就會導致線程競爭,那么在大並發情況下將會出現性能問題,同會引起線程BLOCKED問題

那么如何優化log4j使其執行時間盡量短,防止線程阻塞呢,推薦一下我們組候姐的一篇文章:log4j不同配置對性能的影響

當前我們解決該問題的方式是去掉log4j配置文件中打印行號的選項,然后再執行一輪測試可以看到如下結果:

其實這個案例的優化主要體現在接口耗時上面的優化,從最初的接口耗時352ms優化到了109ms,性能提升了接近3倍,雖然用戶量小的時候,體現不出打的性能瓶頸,如果並發量大,這種性能優化的效果還是很明顯

其實性能優化的重點是分析解決性能瓶頸,而作為專業的性能測試需要輔助開發定位和性能瓶頸卡在哪里,進而指導開發解決問題

 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM