利用jstack定位典型效能問題例項

  問題的起因是筆者在一輪效能測試的中，發現某協議的響應時間很長，去觀察哨兵監控裡的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使用姿勢的一篇ks： 巧用jstack定位效能問題

    我們來jstack一下，檢視在測試執行的過程中，各執行緒所做的操作和執行緒狀態，可以看到以下狀態：

    在所有的24個執行緒中，多執行幾次jstack可以發現大約有十個左右的執行緒處於waitting狀態，該狀態表明該執行緒正在執行obj.wait()方法，放棄了 Monitor，進入 “Wait Set”佇列，為什麼阻塞住呢，繼續往下看堆疊資訊，可以看到該執行緒正在做borrowobject操作，可以大概看到這裡是一個資料庫連線池的相關操作，具體到究竟是幹什麼的可以檢視一些資料庫連線池的資料： dbcp原始碼解讀與物件池原理剖析

    簡單的說一下，資料庫連線的使用過程：建立一個池物件工廠, 將該工廠注入到物件池中, 當要取池物件, 呼叫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死鎖問題）：

/** 
     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配置檔案中列印行號的選項，然後再執行一輪測試可以看到如下結果：     可以看到響應updateSession響應時間又下降了一半到了11.48ms的水平，最佳化到這裡可以看到該dao層方法算是達到了一個正常水平，看總體的響應時間也從原先的352.11ms下降到109.19ms。可以認為解決了該協議的效能問題。    總結下來，可以發現一個典型效能問題的分析思路：發現效能問題-->檢視壓測機，伺服器，資料庫資源指標是否達到瓶頸點-->結合哨兵找到主要耗時方法-->檢視耗時方法的具體程式碼邏輯-->具體問題具體分析(這裡是結合jstack檢視堆疊資訊)-->條件允許範圍內最佳化問題並驗證問題。