壓測暴露的OpenJDK Bug排查實戰(zhàn)

為了持續(xù)保障前臺業(yè)務(wù)的服務(wù)穩(wěn)定、性能穩(wěn)定，京東零售-平臺業(yè)務(wù)中心建設(shè)了線上流量錄制能力，要求測試、研發(fā)團(tuán)隊對于前臺業(yè)務(wù)進(jìn)行常態(tài)化流量回放壓測，常態(tài)化壓測任務(wù)以周、日為周期。京東主站日歷模塊SOA服務(wù)是京東主APP活動日歷的服務(wù)端，測試同學(xué)反饋用于常態(tài)化壓測機(jī)器的壓測性能出現(xiàn)了大幅度衰減，而且這個衰減過程是突然發(fā)生的，在3月30日還是正常的，但是3月31日在同等壓測設(shè)置情況下CPU使用率達(dá)到了90%以上，且QPS大幅度下降，可用率也出現(xiàn)了下降的情況。

3月30日到3月31日的壓測情況具體情況可以看下圖：

出現(xiàn)這個問題后，測試同學(xué)在3月31日進(jìn)行了反饋，由于線上其他機(jī)器沒有任何異常現(xiàn)象，且我們在這段時間內(nèi)沒有進(jìn)行上線、配置修改等，因此我們認(rèn)為本次可能是偶發(fā)的問題，簡單排查UMP監(jiān)控后發(fā)現(xiàn)并無異?，F(xiàn)象，并沒有進(jìn)行深入排查。

在4月1日愚人節(jié)這天，又收到測試同學(xué)反饋常態(tài)化壓測未達(dá)標(biāo)，這時我們意識到問題并沒有想象中的簡單，但是由于壓測機(jī)只有壓測時才會有請求，壓測的時間只會持續(xù)5分鐘，因此無法直接復(fù)現(xiàn)問題現(xiàn)場，因此我們決定手動觸發(fā)常態(tài)化壓測，進(jìn)行問題現(xiàn)場的復(fù)現(xiàn)。

手動觸發(fā)流量回放壓測任務(wù)以后，發(fā)現(xiàn)本次失敗了達(dá)到了100%，這說明此時服務(wù)已經(jīng)進(jìn)入了不可用狀態(tài)，由此推斷出這并不是一個偶現(xiàn)的問題，而是一個存在于線上的問題。但是此時又出現(xiàn)了一個問題，為什么線上其他機(jī)器并沒有出現(xiàn)任何問題，而只有單獨(dú)拿出來的壓測機(jī)出現(xiàn)了問題？

首先我們分析了常態(tài)化壓測的四個接口，其中接口A、B幾乎沒有業(yè)務(wù)邏輯，只是單純的取了配置平臺的配置項，而DUCC平臺的配置項可以視為JVM內(nèi)部的本地緩存，而且DUCC也是我們長期使用的配置平臺，在穩(wěn)定性和性能方面非常的優(yōu)秀，因此排除懷疑這兩個接口。而對于接口C和D，則是直接調(diào)用了上游接口，這里我們首先懷疑是因為上游接口性能出現(xiàn)了問題，導(dǎo)致了接口C和D出現(xiàn)了性能問題。

因此我們對接口C和D的UMP監(jiān)控點進(jìn)行了排查，項目中按照傳統(tǒng)的分層模式分為了Controller層、Service層和Rpc層，每一層級都有單獨(dú)的監(jiān)控點，但是經(jīng)過排查三層監(jiān)控點，發(fā)現(xiàn)可用率是100%且請求得TP999也只有236ms。

這個現(xiàn)象讓我們很詫異，為什么系統(tǒng)內(nèi)監(jiān)控點可用率100%且接口請求耗時Max只有236ms，HTTP接口卻進(jìn)入了一種不可用狀態(tài)？

這里HTTP請求返回了99%以上的錯誤碼是524，HTTP錯誤碼524代表TCP握手完成但是卻沒有及時收到HTTP響應(yīng)。

排查到這里，似乎進(jìn)入了一個僵局，項目內(nèi)部的監(jiān)控點并沒有出現(xiàn)問題，但是服務(wù)器卻不能響應(yīng)請求。這時我們懷疑是這臺機(jī)器的Tomcat服務(wù)器出現(xiàn)了問題，因此產(chǎn)生了重啟服務(wù)器的想法（幸虧沒有這樣做），但是當(dāng)時考慮到如果重啟問題可能就不能復(fù)現(xiàn)，因此決定繼續(xù)在問題現(xiàn)場進(jìn)行排查。

這時想到了UMP-Pfinder提供的調(diào)用鏈監(jiān)控能力，通過查找壓測機(jī)器的請求找到了當(dāng)時的調(diào)用鏈詳情。

可以看到，接口調(diào)用JSF接口耗時總共只有20ms，但是Tomcat處理這次HTTP請求卻耗時8s。這時候事情好像有了一些眉目，因為我們項目內(nèi)的監(jiān)控點，只能監(jiān)控到Controller層的請求耗時，但實際上，Controller層的方法完成調(diào)用返回后，是交給SpringMVC框架處理，SpringMVC框架會進(jìn)行一些HTTP報文的數(shù)據(jù)封裝，而SpringMVC框架也是繼承實現(xiàn)了Servlet-API，最終完成收發(fā)HTTP報文的則是被稱為container（容器）的軟件，就比如我們常用的Tomcat、Jetty等，實際上的調(diào)用路徑如下圖：

既然系統(tǒng)內(nèi)監(jiān)控點沒有異常，而本次HTTP請求出現(xiàn)了問題，那么是不是有可能SpringMVC框架或者Tomcat出現(xiàn)了Bug呢？

雖然懷疑是SpringMVC或者Tomcat出了問題，但是也并沒有太好的切入點去排查，因此還是需要從壓測機(jī)器的JVM狀況排查，首先我們通過UMP提供的JVM監(jiān)控能力，發(fā)現(xiàn)最后一次手動觸發(fā)壓測任務(wù)時，JVM的GC情況、堆內(nèi)存情況一切正常，CPU使用率也只有75%左右。

但是同比之前壓測時間段內(nèi)，我們發(fā)現(xiàn)VM的線程數(shù)由200個以內(nèi)激增到了1000多個，因此我們重啟了壓測任務(wù)，在任務(wù)執(zhí)行期間對壓測機(jī)使用jstack工具dump了線程堆棧。

有了線程堆棧Dump樣本以后，我們開始對線程進(jìn)行分析，分析線程堆棧的工具有很多，這里我們選用了perfma提供的社區(qū)產(chǎn)品分析線程狀態(tài)。

經(jīng)過分析發(fā)現(xiàn)有1043個線程處于WAITING狀態(tài)，這種現(xiàn)象是很反常的，按照經(jīng)驗，這種現(xiàn)象說明VM內(nèi)部可能存在死鎖或者存在存在競爭激烈且持鎖時間比較長的線程，通過進(jìn)一步分析發(fā)現(xiàn)，http-nio-1601-exec-*線程池中包含1000個線程，且有999個都處于WAITING狀態(tài)。

http-nio-1601-exec-xxx 線程是Tomcat在1601端口的的工作線程。我們知道，Tomcat的工作線程數(shù)量可以通過max-threads配置項配置，這里我們配置了max-threads為1000，所以Tomcat的工作線程最大也只能有1000個，但是對于正常負(fù)載的服務(wù)器來說，線程池中的線程數(shù)會低于最大值的一半，也就是說會在500個以內(nèi)，且處于WAITING狀態(tài)的工作線程，一般都會處于等待數(shù)據(jù)庫IO、RPC方法調(diào)用的狀態(tài)，而對于較低負(fù)載的服務(wù)器來說，線程數(shù)甚至只有min-SpareThreads配置的最小值，而且大部分線程會處于等待線程池中任務(wù)隊列的狀態(tài)。

繼續(xù)追查WAITING狀態(tài)的線程，發(fā)現(xiàn)999個線程全部阻塞在org.springframework.util.MimeTypeUtils$ConcurrentLruCache.get 方法內(nèi)部的讀寫鎖上。

而唯一運(yùn)行中的線程，也在執(zhí)行org.springframework.util.MimeTypeUtils$ConcurrentLruCache.get方法，且堆棧在ConcurrentLinkedQueue的remove方法。

排查到這里，我們開始懷疑是org.springframework.util.MimeTypeUtils類中ConcurrentLruCache內(nèi)部類的get方法存在問題。

查看Spring框架源碼，發(fā)現(xiàn)這塊邏輯就是實現(xiàn)了一個LRU緩存，通過ConcurrentLinkedQueue保證線程安全的同時，實現(xiàn)了淘汰最近最久未使用的緩存key（這里緩存value其實就是HTTP MIME類型），因此在搜索引擎上進(jìn)行搜索，發(fā)現(xiàn) spring-framework 工程Github上有多個Issues，反饋MimeTypeUtils類出現(xiàn)性能衰減問題，導(dǎo)致CPU占用率飆升問題。最終Spring開發(fā)者認(rèn)定了這些問題源自同一個Bug。

后續(xù)Spring開發(fā)者修復(fù)了這個問題，修復(fù)方式是將ConcurrentLinkedQueue換為了ConcurrentLinkedDeque。

到這里我們已經(jīng)可以解決這個問題，只需要升級Spring框架版本號就可以避開這個Bug，但是有個問題始終縈繞在我心中，因為查看源碼，作者對于這個LRU緩存做了一個最大長度的限制，超過這個maxSize就會淘汰緩存remove元素，為什么會出現(xiàn)Spring開發(fā)者說的內(nèi)存泄漏和隊列無限增長的問題呢？

帶著好奇心繼續(xù)查找相關(guān)資料，發(fā)現(xiàn)JDK-8137184匯報了一個ConcurrentLinkedQueue#remove(Object)導(dǎo)致內(nèi)存溢出的Bug，但是這個Bug在2015年9月已經(jīng)被解決了，難道說和這個Bug沒有關(guān)系？

因此我去下載了我們使用的JDK源碼壓縮包，找到ConcurrentLinkedQueue類的源碼后，發(fā)現(xiàn)其其中remove方法的Bug依舊是存在的。

為什么會這樣呢？原來服務(wù)器上使用的是開源的Open JDK，Open JDK修復(fù)這個Bug時間較晚，在8u102版本才合并修復(fù)，這樣就能解釋我們所使用的Open JDK版本為什么依然存在這個Bug了。

這個Bug具體會造成什么現(xiàn)象呢？這里我找到了JDK的Bug報告：

The remove code both nulls the item value and then attempts to delink the pred next node pointer. However, if the current node next pointer is null (ie the last item), then the pred node next is not nulled. Thus the list grows forever!

根據(jù)Bug報告，remove方法應(yīng)該把隊列中需要刪除的元素所在的節(jié)點值置為null，同時將節(jié)點從隊列中delink（解鏈），這個很好理解，我們都知道鏈表在刪除元素時需要解鏈（參考最簡單的LinkedList），但是當(dāng)這里的remove方法需要移除的元素位于鏈表中最后一個節(jié)點時，并不會移除最后一個節(jié)點，從而導(dǎo)致了鏈表的無限增長。

這里我們拿從服務(wù)器上下載的JDK源碼，找到存在Bug的ConcurrentLinkedQueue類的源碼來看下：

// ConcurrentLinkedQueue類有Bug的remove方法public boolean remove(Object o) {    if (o == null) return false;    Node<E> pred = null;    for (Node<E> p = first(); p != null; p = succ(p)) { // 遍歷鏈表        E item = p.item;        if (item != null &&            o.equals(item) &&            p.casItem(item, null)) {            Node<E> next = succ(p);            // 這里出現(xiàn)了問題，p為最后一個元素時，succ(p)返回null            // next=null，就導(dǎo)致下面這一行if判斷永遠(yuǎn)為false            // 也就是說永遠(yuǎn)都不會移除這個節(jié)點            if (pred != null && next != null)                pred.casNext(p, next); // 刪除節(jié)點            return true;        }        pred = p;    }    return false;}

根據(jù)源碼，可以很清晰的看明白這個Bug的成因，當(dāng)需要remove的元素在鏈表的最后時，確實不會移除這個節(jié)點。

舉個例子來說，如果先add或者offer元素2到鏈表中，下一步又直接remove這個元素2，重復(fù)這個過程，就會導(dǎo)致這個鏈表無限增長，又因為remove會遍歷列表，這就可能導(dǎo)致remove遍歷的時間越來越長，從而產(chǎn)生了之前我們服務(wù)器上999個線程都在等待1個線程remove方法執(zhí)行。

理論上來說，這個Bug一定會導(dǎo)致JVM堆內(nèi)存泄漏，使用jmap工具Dump線上機(jī)器堆內(nèi)存以后，導(dǎo)入MAT分析后，發(fā)現(xiàn)確實存在內(nèi)存泄漏的問題，線上機(jī)器并沒有出現(xiàn)這個問題可能是因為這個列表還不夠大，remove遍歷時間還不至于導(dǎo)致服務(wù)不可用。

分析Dump文件以后，發(fā)現(xiàn)ConcurrentLinkedQueue的Node節(jié)點對象有74萬個，而Spring框架MimeTypeUtils內(nèi)的LRU緩存列表queue變量RetainedHeap大小幾乎等于全部74萬個Node對象的大小，也就是說明確實是MimeTypeUtils類內(nèi)LRU緩存列表發(fā)生了內(nèi)存泄漏。

JDK修復(fù)這個Bug的方式也比較簡單，之前Bug產(chǎn)生的原因是因為remove方法刪除最后一個元素時只把item值置為null，但是卻并不能解鏈，導(dǎo)致在不斷地add\remove中這個鏈表越來越長，既然這樣，就在下次remove時把之前item為null的節(jié)點解鏈，JDK開發(fā)者就是這樣修復(fù)了這個Bug。

// 修復(fù)Bug后的remove方法public boolean remove(Object o) {    if (o != null) {        Node<E> next, pred = null;        for (Node<E> p = first(); p != null; pred = p, p = next) {            boolean removed = false;            E item = p.item;                        // 這里if判斷item是否為null            // item為null說明是上次刪除遺留的空節(jié)點，進(jìn)入后續(xù)解鏈邏輯            // item不為null則進(jìn)入判斷是否需要刪除邏輯            if (item != null) {                 if (!o.equals(item)) {                    // 不是要刪除元素，則繼續(xù)向后遍歷                    next = succ(p);                    continue;                }                // 要刪除元素item值置為null                removed = p.casItem(item, null);            }                        next = succ(p);            // 這里判斷邏輯和之前一樣，本次remove最后一個元素，依舊不會解鏈            // 但是上次remove最后一個元素后遺留的null節(jié)點，會在本次被解鏈            if (pred != null && next != null) // unlink                pred.casNext(p, next);            if (removed)                return true;        }    }    return false;}

舉個簡單例子來說，如果我們依舊一直add\remove 元素2，那么就會出現(xiàn)下圖這個情況，本次remove只把隊尾的元素2所在的節(jié)點item置為null，而下次remove時就會把這個item=null的節(jié)點從鏈表中真正的移除，被移除的節(jié)點會失去和GCRoot連接，最終在下次GC中被回收，從而保證不會出現(xiàn)內(nèi)存泄漏的問題。

本次問題排查過程中，遇到了一些超出平常接觸到的問題，也出現(xiàn)了想重啟服務(wù)器嘗試“解決”問題的錯誤思路，同時也因為這些障礙，我萌發(fā)了更多思路、借助了更多的新工具，比如說UMP平臺新提供的鏈路追蹤功能，就是我破局的一個重要倚賴。

出現(xiàn)了匪夷所思的問題，首先要保留好問題現(xiàn)場，比如說將VM堆和線程堆棧Dump保存，保存線上日志和GC信息等，特別是一些不能必現(xiàn)的問題，更需要問題現(xiàn)場才能進(jìn)行排查，盲目的嘗試重啟解決問題，反而會掩蓋存在的問題。

— 本文結(jié)束 —

● 漫談設(shè)計模式在 Spring 框架中的良好實踐

● 顛覆微服務(wù)認(rèn)知：深入思考微服務(wù)的七個主流觀點

● 人人都是 API 設(shè)計者

● 一文講透微服務(wù)下如何保證事務(wù)的一致性

● 要黑盒測試微服務(wù)內(nèi)部服務(wù)間調(diào)用，我該如何實現(xiàn)？

在看點這里