此文已由作者朱笑天授權網易雲社區發布。
歡迎訪問網易雲社區，了解更多網易技術產品運營經驗。
問題的起因是筆者在一輪性能測試的中，發現某協議的響應時間很長，去觀察哨兵監控里的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查看堆棧信息)-->條件允許范圍內優化問題並驗證問題。
更多網易技術、產品、運營經驗分享請點擊。
相關文章：
【推薦】 知物由學 | 基於DNN的人臉識別中的反欺騙機制
【推薦】 網易嚴選后台系統前端規范化解決方案
【推薦】 Android TV 開發（2）