性能優化案例（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倍，雖然用戶量小的時候，體現不出打的性能瓶頸，若是併發量大，這種性能優化的效果仍是很明顯

其實性能優化的重點是分析解決性能瓶頸，而做爲專業的性能測試須要輔助開發定位和性能瓶頸卡在哪裏，進而指導開發解決問題