利用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不一樣配置對性能的影響 當前咱們解決該問題的方式是去掉log4j配置文件中打印行號的選項，而後再執行一輪測試能夠看到以下結果： 能夠看到響應updateSession響應時間又降低了一半到了11.48ms的水平，優化到這裏能夠看到該dao層方法算是達到了一個正常水平，看整體的響應時間也從原先的352.11ms降低到109.19ms。能夠認爲解決了該協議的性能問題。 總結下來，能夠發現一個典型性能問題的分析思路：發現性能問題-->查看壓測機，服務器，數據庫資源指標是否達到瓶頸點-->結合哨兵找到主要耗時方法-->查看耗時方法的具體代碼邏輯-->具體問題具體分析(這裏是結合jstack查看堆棧信息)-->條件容許範圍內優化問題並驗證問題。

免費體驗雲安全(易盾)內容安全、驗證碼等服務

更多網易技術、產品、運營經驗分享請點擊。

相關文章：
【推薦】 在一臺服務器上搭建相對高可用HiveServer實踐
【推薦】 深情留不住，套路得人心- -聊聊套路那些事兒
【推薦】 編寫一個供瀏覽器端使用的NPM包