記一次閒魚線上問題的排查——一把無人持有的鎖

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問題時，可參考本文所述的方法與步驟，對實際問題進行分析與研究。