記一次閑魚線上問題的排查——一把無人持有的鎖
1 背景
近期，閑魚核心應用出現了一個比較難解決的問題。在該應用叢集中，會随機偶現一兩個執行個體，其JVM運作在一個挂起的狀态，深入分析stack檔案發現，此時jvm中有大量的線程在等待一把沒有任何線程持有的鎖。問題執行個體所在的機器負載相對正常機器要輕很多，而其線程數則大幅增多。由于該問題在邏輯上的沖突，加上周邊問題的複雜性，使得研究、分析、解決該問題變得相對來說困難與曲折。本文将系統性地介紹如何解決這個問題，并找出問題背後的原因。
2 問題分析
在實際解決這個問題的時候，我們發現不僅問題本身顯得不合常理，其周邊環境也相對來說不友善，給問題的分析與解決帶來了較大的困難。
- 叢集中随機出現。問題随機出現在該應用叢集中的一個或幾個執行個體中，無法提前預知其出現規律。
- 單機出現時間不可預知，現場捕捉困難，捕捉風險大，一般發現已經為事後，無現場第一手資料。上述問題換個角度看，從單個機器，或者單個執行個體看，則是出現機率非常低，出現時間完全随機。這使得蹲點單台機器以捕捉這個問題的思路幾乎行不通，政策擴大至整個叢集又可能出現穩定性及性能問題。
- 問題出現頻率低。出現頻率大概在一到兩天一次。
- 複現困難。無法在生産環境直接對分析結果進行複現驗證。
- 問題表現複雜。該問題的表現很複雜，不僅從第一眼看去不合常理，JVM内部出現了大量線程在等待一把沒有任何線程持有的鎖。另外，問題機器的負載非常低，基本上在5%以内，相當與空載，而JVM中線程數卻非常多，最多發現過接近4k個線程。
- 問題周邊環境複雜。在問題出現前後，該應用部分提供的服務引入了rxjava，rxjava本身在運作過程中會大量建立線程。該應用基于阿裡JDK，采用了協程機制，stack檔案顯示問題機器最多的棧是協程對應的棧。問題執行個體中大多數的鎖和log4j相關，而網上大量的針對log4j使JVM挂起的情形又和該問題的表現不符。另外，該應用曆史悠久，作為閑魚早期的核心應用，服務結構複雜，不僅有針對前端的http服務，還有面向底層的基礎服務，服務跨層現象明顯。
- 驗證困難。理論分析完成後，無法線上上驗證，安全性、穩定性、資料等都不允許直接線上上驗證。
3 問題解決方案
解決這個問題的主要按照以下六步，一步步排除法，最終定位并解決問題。按照先易後難，先直接後理論，先資料後源碼的順序，總結出來以下六步，大體上投入時間逐漸增加，難度也逐漸增加。
3.1 代碼bug查找
代碼問題指的是業務代碼本身邏輯問題把JVM帶入了某種故障狀态。問題的分析及排除很簡單，通過觀察應用日志即可。
3.2 現場捕獲
定位了問題，問題也就解決了一半。
一般來說，定位問題主要有兩個分類，即時定位，事後定位。前一種是指我們實時直接監控JVM資訊，在關鍵資訊異常時，即發生動作。配合周期性的資訊采集，基本可以對問題發生時刻前後資料精準采集和對比。做法一般是采用JVM代理方式或JMS方式。JVM代理分為C語言和Java語言代理，C語言代理運作在JVM層，可以做到即時Java代碼發生故障故障，依然可以正常采集資訊。Java代理相對C語言代理來說編寫起來友善，實際上C語言部分任務還是通過JNI接口構造Java對象執行的。JMS方式可以實時采集各種名額，也是目前監控主要采用等方式。缺點是對應用的侵入性非常大，不适合解決問題用。事後定位是指通過日志監控等較緩慢的方式去對問題發生時刻定位，由于該問題的特殊性，日志無法提供需要的資訊以判斷故障，另外，日志無法采集我們需要的資訊，尤其是JVM内部線程和鎖的資訊。
在後續現象的觀察中，發現了一個比較普遍的現象，應用由正常轉為故障需要一個漫長的時間，應用可能在臨界區停留相當長的時間，極端例子中應用線上程數提升後依然能夠正常運作接近24小時，之後發生了自恢複。另外，在和JVM組同學對接的時候，又被告知阿裡jdk對C代理支援可能由于安全原因被關閉。基本上宣布這個問題的研究進入了下一個階段。
3.3 io hang
考慮到大部分執行個體業務日志列印緩慢或者根本不再列印，可能原因是io方面出了問題，通過檢視容器硬體監控及應用火焰圖，可以輕松将IO問題排除。
3.4 鎖分析
鎖問題主要包含死鎖和丢鎖。死鎖的特點很明顯，一旦發生死鎖，則與該鎖相關的線程都将停止。首先這點和大量執行個體運作緩慢不符，其次，這個問題可以輕易通過stack檔案排除。
丢鎖主要和協程有關，和死鎖相似，考慮到協程可能在切換過程中發生丢鎖，造成的現象和該問題很類似，即沒有線程持有的鎖。丢鎖最主要的問題也是不可恢複，一旦丢鎖，則JVM相關線程就永遠不可恢複，和該問題不符。另外，觀察大部分stack檔案發現，此時JVM中的協程數量并不多，線程池Worker執行個體也在變化。
3.5 資源耗盡檢視
資源耗盡是指JVM運作過程中由于部分資源緊張，程式雖然可以正常運作，但是限于部分資源緊張，必須等待其他線程釋放了持有資源後，目前線程才可以繼續運作。資源包括軟體資源和硬體資源。
軟體資源是指在JVM運作過程中，有設定上限的軟體資源，如堆、Reserved Code Cache、中繼資料區等，在實際觀察中，發現上述資源均未出現明顯的資源耗盡情況。
硬體資源主要分析在JVM運作過程中，所在機器硬體資源如CPU、記憶體、網絡等硬體資源使用情況。其中，在觀察中發現，記憶體資源出現了明顯的問題，由于問題機器線程數大幅增加，導緻問題機器JVM總使用記憶體超出了機器的實體記憶體。加上監控程序與機器本身的程序，很容易得出一個結論，JVM此時在将部分資源扇出至page頁。實際上，JVM此時在部分基于硬碟運作。如果此時JVM進行一個牽涉面很廣的搶鎖任務，那麼就有可能發生悲劇。
而在該問題中，應用采用了log4j作為日志記錄工具，檢視相關源碼可以看出，log4j采用了java monitor來控制日志列印，防止日志結構混亂及資料破壞。而作為流量入口日志，所有的業務線程都會進行進行列印，是以也會進行搶鎖。
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);
}
} 檢視HotSpot源碼，在退出臨界區時，首先要做的是把鎖狀态重置，也即對象頭重置及Montior對象目前owner置NULL，然後才會喚醒所有相關線程搶鎖。如果此時記憶體放不下所有有關線程，随着線程的喚醒，活躍線程會被扇出以提供記憶體空間。大量的扇入和扇出使得這個過程顯得很緩慢，也就出現了一個沒有任何線程持有的鎖，實際上JVM此時在進行一個艱難的搶鎖任務。
for (p = w ; p != NULL ; p = p->_next) {
guarantee (p->TState == ObjectWaiter::TS_CXQ, "Invariant") ;
p->TState = ObjectWaiter::TS_ENTER ;
p->_prev = q ;
q = p ;
}
// Prepend the RATs to the EntryList
if (_EntryList != NULL) {
q->_next = _EntryList ;
_EntryList->_prev = q ;
} 3.6 架構層源碼閱讀
在前面步驟中大緻定位了一個大的方向，線程數增加導緻記憶體不足。接下來需要深入架構層去分析引起線程數增加的可能原因。
先後對HSF、Modulet、Mtop、netty等架構進行了源碼級别的分析，主要跟蹤各個架構線程配置設定政策。其中，HSF預設設定的線程池模型擾動抗性很低。在HSF架構中，netty線程池将任務送出到HSF Provider線程池，HSF Provider線程池采用業務隔離設計，在一次對外服務中，HSF Provider大量調用HSF Consumer，而Consumer會被送出至Consumer線程池中執行。在該應用中，Provider和Consumer線程池容量比例大于200:1。
而根據業務實際，合理的比例應該在1:1附近。
失衡的線程池結構，極容易服務發生網絡抖動、回環調用時使Consumer線程池服務能力下降，進而使整個應用執行個體對外服務能力下降。而有規律的故障不應該和無規律的抖動有關。
回環與問題出現頻率之間讀者可以通過機率論進行分析，假定100台機器，則每次請求會有1/100的機率發生回環，同理，每10000次請求就會發生雙回環，1M次請求則是3回環。在該問題中，機率論分析和實際情況是契合的。
在研究架構層的時候，發現了回環調用對系統的危害。但是還有一個疑問需要回答，回環調用完成後，應用應該能恢複，而線上實際情況是，自恢複是個小機率事件。結合前一節可以得出一個結論，回環調用使應用Consumer線程池處理能力下降，進而使上遊線程池水位逐漸提升直至被打滿。而數量過度增加的線程池使得記憶體資源緊張，導緻JVM基于磁盤運作而搶鎖困難，搶鎖過程的拉長使得沒有任何線程持有鎖這個正常狀态下的瞬時狀态被拉長，JVM服務能力大打折扣，而duct平台由于政策原因不能應對該問題的特殊情況導緻其無法啟動切流，流量照常打入JVM。于是就形成了一個惡性循環，線程數提升導緻JVM進入一種非正常狀态，服務能力下降，而流量照常，導緻線程數很難下降。于是，JVM長時間運作在一個非常緩慢的狀态，從表現上來看就是jvm挂起。
下表為一個較有代表性的流量對比（實際上故障機狀态跨度非常大，這兩台機器較為典型而已）
| 流量 | |
|---|---|
| 正常機器 | 169k |
| 故障機器 | 6k |
4 實驗驗證
接下來，本文采用阿裡PAS壓測平台，對預發機器進行了壓測驗證。由于線上問題複雜，無法複現線上的環境，隻能對其誘因進行驗證。
下表為壓測過程中應用的性能表現。由于壓測模式限制，所支援的最大tps在逾時的情況下非常低，如表所示隻有80左右，考慮到壓測環境機器數量，回環數量還要打折。
| TPS | RT(ms) | 80%RT(ms) | 95%RT(ms) |
|---|---|---|---|
| 77.41 | 2523.12 | 3103.9 | 5005.84 |
從下圖可以看出，平均RT為2500ms左右，絕大多數請求都在逾時狀态。
壓測結果表明，回環不需要多高的流量，就能把應用實際服務能力大打折扣。考慮到線上還有其他類型的請求，填充在回環之間，這會使線程池迅速打滿，并使得處理回環請求的時間加長，惡化應用從回環調用中恢複的能力。
5 總結
在JVM出現問題的時候，首先要閱讀業務代碼，這個雖然看似作用不大，卻有可能以相當低廉的代價解決問題。之後，主要思路就是捕獲現場，現場捕獲将極大程度上有助于問題的解決。如果該步驟不可行，或者成本相對較高，可以先去排查周邊原因。這主要包括IO、鎖、硬軟體資源，在執行這些排查的時候，要留意這些方面出問題的表現和實際問題的表現契合度。比較明顯的就是一旦死鎖、丢鎖，或者IO hang，則程式無法從故障狀态恢複，相關線程也不能繼續執行。這些特點可以協助排除部分大的方向。最後，對資源耗盡的排查，則是基于本文所述問題的一個基本特點，絕大多數JVM運作緩慢而不是停止運作。是以，資源緊張成為一個解決問題的大方向，并最終定位了問題。深入到架構層主要是從理論上分析問題産生的原因，然後在結合實際情況，分析整個解決思路的正确性。讀者在遇到類似JVM問題時，可參考本文所述的方法與步驟，對實際問題進行分析與研究。