Java內存泄漏排查過程的示例分析

這篇文章給大家分享的是有關Java內存泄漏排查過程的示例分析的內容。小編覺得挺實用的，因此分享給大家做個參考，一起跟隨小編過來看看吧。

在一個凄涼的午夜

午夜剛過，我就被一條來自監(jiān)控系統(tǒng)的警報吵醒了。Adventory，我們的 PPC （以點擊次數(shù)收費）廣告系統(tǒng)中一個負責索引廣告的應用，很明顯連續(xù)重啟了好幾次。在云端的環(huán)境里，實例的重啟是很正常的，也不會觸發(fā)報警，但這次實例重啟的次數(shù)在短時間內超過了閾值。我打開了筆記本電腦，一頭扎進項目的日志里。

一定是網(wǎng)絡的問題

我看到服務在連接 ZooKeeper 時發(fā)生了數(shù)次超時。我們使用 ZooKeeper（ZK）協(xié)調多個實例間的索引操作，并依賴它實現(xiàn)魯棒性。很顯然，一次 Zookeeper 失敗會阻止索引操作的繼續(xù)運行，不過它應該不會導致整個系統(tǒng)掛掉。而且，這種情況非常罕見（這是我第一次遇到 ZK 在生產(chǎn)環(huán)境掛掉），我覺得這個問題可能不太容易搞定。于是我把 ZooKeeper 的值班人員喊醒了，讓他們看看發(fā)生了什么。

同時，我檢查了我們的配置，發(fā)現(xiàn) ZooKeeper 連接的超時時間是秒級的。很明顯，ZooKeeper 全掛了，由于其他服務也在使用它，這意味著問題非常嚴重。我給其他幾個團隊發(fā)了消息，他們顯然還不知道這事兒。

ZooKeeper 團隊的同事回復我了，在他看來，系統(tǒng)運行一切正常。由于其他用戶看起來沒有受到影響，我慢慢意識到不是 ZooKeeper 的問題。日志里明顯是網(wǎng)絡超時，于是我把負責網(wǎng)絡的同事叫醒了。

負責網(wǎng)絡的團隊檢查了他們的監(jiān)控，沒有發(fā)現(xiàn)任何異常。由于單個網(wǎng)段，甚至單個節(jié)點，都有可能和剩余的其他節(jié)點斷開連接，他們檢查了我們系統(tǒng)實例所在的幾臺機器，沒有發(fā)現(xiàn)異常。其間，我嘗試了其他幾種思路，不過都行不通，我也到了自己智力的極限。時間已經(jīng)很晚了（或者說很早了），同時，跟我的嘗試沒有任何關系，重啟變得不那么頻繁了。由于這個服務僅僅負責數(shù)據(jù)的刷新，并不會影響到數(shù)據(jù)的可用性，我們決定把問題放到上午再說。

一定是 GC 的問題

有時候把難題放一放，睡一覺，等腦子清醒了再去解決是一個好主意。沒人知道當時發(fā)生了什么，服務表現(xiàn)的非常怪異。突然間，我想到了什么。Java 服務表現(xiàn)怪異的主要根源是什么？當然是垃圾回收。

為了應對目前這種情況的發(fā)生，我們一直打印著 GC 的日志。我馬上把 GC 日志下載了下來，然后打開 Censum開始分析日志。我還沒仔細看，就發(fā)現(xiàn)了一個恐怖的情況：每15分鐘發(fā)生一次 full GC，每次 GC 引發(fā)長達 20 秒的服務停頓。怪不得連接 ZooKeeper 超時了，即使 ZooKeeper 和網(wǎng)絡都沒有問題。

這些停頓也解釋了為什么整個服務一直是死掉的，而不是超時之后只打一條錯誤日志。我們的服務運行在 Marathon 上，它定時檢查每個實例的健康狀態(tài)，如果某個端點在一段時間內沒有響應，Marathon 就重啟那個服務。

知道原因之后，問題就解決一半了，因此我相信這個問題很快就能解決。為了解釋后面的推理，我需要說明一下 Adventory 是如何工作的，它不像你們那種標準的微服務。

Adventory 是用來把我們的廣告索引到 ElasticSearch (ES) 的。這需要兩個步驟。第一步是獲取所需的數(shù)據(jù)。到目前為止，這個服務從其他幾個系統(tǒng)中接收通過 Hermes 發(fā)來的事件。數(shù)據(jù)保存到 MongoDB 集群中。數(shù)據(jù)量最多每秒幾百個請求，每個操作都特別輕量，因此即便觸發(fā)一些內存的回收，也耗費不了多少資源。第二步就是數(shù)據(jù)的索引。這個操作定時執(zhí)行（大概兩分鐘執(zhí)行一次），把所有 MongoDB 集群存儲的數(shù)據(jù)通過 RxJava 收集到一個流中，組合為非范式的記錄，發(fā)送給 ElasticSearch。這部分操作類似離線的批處理任務，而不是一個服務。

由于經(jīng)常需要對數(shù)據(jù)做大量的更新，維護索引就不太值得，所以每執(zhí)行一次定時任務，整個索引都會重建一次。這意味著一整塊數(shù)據(jù)都要經(jīng)過這個系統(tǒng)，從而引發(fā)大量的內存回收。盡管使用了流的方式，我們也被迫把堆加到了 12 GB 這么大。由于堆是如此巨大（而且目前被全力支持），我們的 GC 選擇了 G1。

我以前處理過的服務中，也會回收大量生命周期很短的對象。有了那些經(jīng)驗，我同時增加了 -XX:G1NewSizePercent 和 -XX:G1MaxNewSizePercent 的默認值，這樣新生代會變得更大，young GC 就可以處理更多的數(shù)據(jù)，而不用把它們送到老年代。Censum 也顯示有很多過早提升。這和一段時間之后發(fā)生的 full GC 也是一致的。不幸的是，這些設置沒有起到任何作用。

接下來我想，或許生產(chǎn)者制造數(shù)據(jù)太快了，消費者來不及消費，導致這些記錄在它們被處理前就被回收了。我嘗試減小生產(chǎn)數(shù)據(jù)的線程數(shù)量，降低數(shù)據(jù)產(chǎn)生的速度，同時保持消費者發(fā)送給 ES 的數(shù)據(jù)池大小不變。這主要是使用背壓（backpressure）機制，不過它也沒有起到作用。

一定是內存泄漏

這時，一個當時頭腦還保持冷靜的同事，建議我們應該做一開始就做的事情：檢查堆中的數(shù)據(jù)。我們準備了一個開發(fā)環(huán)境的實例，擁有和線上實例相同的數(shù)據(jù)量，堆的大小也大致相同。把它連接到 jnisualvm ，分析內存的樣本，我們可以看到堆中對象的大致數(shù)量和大小。大眼一看，可以發(fā)現(xiàn)我們域中Ad對象的數(shù)量高的不正常，并且在索引的過程中一直在增長，一直增長到我們處理的廣告的數(shù)量級別。但是……這不應該啊。畢竟，我們通過 RX 把這些數(shù)據(jù)整理成流，就是為了防止把所有的數(shù)據(jù)都加載到內存里。

隨著懷疑越來越強，我檢查了這部分代碼。它們是兩年前寫的，之后就沒有再被仔細的檢查過。果不其然，我們實際上把所有的數(shù)據(jù)都加載到了內存里。這當然不是故意的。由于當時對 RxJava 的理解不夠全面，我們想讓代碼以一種特殊的方式并行運行。為了從 RX 的主工作流中剝離出來一些工作，我們決定用一個單獨的 executor 跑 CompetableFuture。但是，我們因此就需要等待所有的 CompetableFuture 都工作完……通過存儲他們的引用，然后調用 join()。這導致一直到索引完成，所有的 future 的引用，以及它們引用到的數(shù)據(jù)，都保持著生存的狀態(tài)。這阻止了垃圾收集器及時的把它們清理掉。

真有這么糟糕嗎？

當然這是一個很愚蠢的錯誤，對于發(fā)現(xiàn)得這么晚，我們也很惡心。我甚至想起很久之前，關于這個應用需要 12 GB 的堆的問題，曾有個簡短的討論。12 GB 的堆，確實有點大了。但是另一方面，這些代碼已經(jīng)運行了將近兩年了，沒有發(fā)生過任何問題。我們可以在當時相對容易的修復它，然而如果是兩年前，這可能需要我們花費更多的時間，而且相對于節(jié)省幾個 G 的內存，當時我們有很多更重要的工作。

因此，雖然從純技術的角度來說，這個問題如此長時間沒解決確實很丟人，然而從戰(zhàn)略性的角度來看，或許留著這個浪費內存的問題不管，是更務實的選擇。當然，另一個考慮就是這個問題一旦發(fā)生，會造成什么影響。我們幾乎沒有對用戶造成任何影響，不過結果有可能更糟糕。軟件工程就是權衡利弊，決定不同任務的優(yōu)先級也不例外。

還是不行

有了更多使用 RX 的經(jīng)驗之后，我們可以很簡單的解決 ComplerableFurue 的問題。重寫代碼，只使用 RX；在重寫的過程中，升級到 RX2；真正的流式處理數(shù)據(jù)，而不是在內存里收集它們。這些改動通過 code review 之后，部署到開發(fā)環(huán)境進行測試。讓我們吃驚的是，應用所需的內存絲毫沒有減少。內存抽樣顯示，相較之前，內存中廣告對象的數(shù)量有所減少。而且對象的數(shù)量現(xiàn)在不會一直增長，有時也會下降，因此他們不是全部在內存里收集的。還是老問題，看起來這些數(shù)據(jù)仍然沒有真正的被歸集成流。

那現(xiàn)在是怎么回事？

相關的關鍵詞剛才已經(jīng)提到了：背壓。當數(shù)據(jù)被流式處理，生產(chǎn)者和消費者的速度不同是很正常的。如果生產(chǎn)者比消費者快，并且不能把速度降下來，它就會一直生產(chǎn)越來越多的數(shù)據(jù)，消費者無法以同樣的速度處理掉他們?，F(xiàn)象就是未處理數(shù)據(jù)的緩存不斷增長，而這就是我們應用中真正發(fā)生的。背壓就是一套機制，它允許一個較慢的消費者告訴較快的生產(chǎn)者去降速。

我們的索引系統(tǒng)沒有背壓的概念，這在之前沒什么問題，反正我們把整個索引都保存到內存里了。一旦我們解決了之前的問題，開始真正的流式處理數(shù)據(jù)，缺少背壓的問題就變得很明顯了。

這個模式我在解決性能問題時見過很多次了：解決一個問題時會浮現(xiàn)另一個你甚至沒有聽說過的問題，因為其他問題把它隱藏起來了。如果你的房子經(jīng)常被淹，你不會注意到它有火災隱患。

修復由修復引起的問題

在 RxJava 2 里，原來的 Observable 類被拆成了不支持背壓的 Observable 和支持背壓的 Flowable。幸運的是，有一些簡單的辦法，可以開箱即用的把不支持背壓的 Observable 改造成支持背壓的 Flowable。其中包含從非響應式的資源比如 Iterable 創(chuàng)建 Flowable。把這些 Flowable 融合起來可以生成同樣支持背壓的 Flowable，因此只要快速解決一個點，整個系統(tǒng)就有了背壓的支持。

有了這個改動之后，我們把堆從 12 GB 減少到了 3 GB ，同時讓系統(tǒng)保持和之前同樣的速度。我們仍然每隔數(shù)小時就會有一次暫停長達 2 秒的 full GC，不過這比我們之前見到的 20 秒的暫停（還有系統(tǒng)崩潰）要好多了。

再次優(yōu)化 GC

但是，故事到此還沒有結束。檢查 GC 的日志，我們注意到大量的過早提升，占到 70%。盡管性能已經(jīng)可以接受了，我們也嘗試去解決這個問題，希望也許可以同時解決 full GC 的問題。

如果一個對象的生命周期很短，但是它仍然晉升到了老年代，我們就把這種現(xiàn)象叫做過早提升（premature tenuring）（或者叫過早升級）。老年代里的對象通常都比較大，使用與新生代不同的 GC 算法，而這些過早提升的對象占據(jù)了老年代的空間，所以它們會影響 GC 的性能。因此，我們想竭力避免過早提升。

我們的應用在索引的過程中會產(chǎn)生大量短生命周期的對象，因此一些過早提升是正常的，但是不應該如此嚴重。當應用產(chǎn)生大量短生命周期的對象時，能想到的第一件事就是簡單的增加新生代的空間。默認情況下，G1 的 GC 可以自動的調整新生代的空間，允許新生代使用堆內存的 5% 至 60%。我注意到運行的應用里，新生代和老年代的比例一直在一個很寬的幅度里變化，不過我依然動手修改了兩個參數(shù)：-XX:G1NewSizePercent=40 和 -XX:G1MaxNewSizePercent=90看看會發(fā)生什么。這沒起作用，甚至讓事情變得更糟糕了，應用一啟動就觸發(fā)了 full GC。我也嘗試了其他的比例，不過最好的情況就是只增加 G1MaxNewSizePercent而不修改最小值。這起了作用，大概和默認值的表現(xiàn)差不多，也沒有變好。

嘗試了很多辦法后，也沒有取得什么成就，我就放棄了，然后給 Kirk Pepperdine 發(fā)了封郵件。他是位很知名的 Java 性能專家，我碰巧在 Allegro 舉辦的 Devoxx 會議的訓練課程里認識了他。通過查看 GC 的日志以及幾封郵件的交流，Kirk 建議試試設置 -XX:G1MixedGCLiveThresholdPercent=100。這個設置應該會強制 G1 GC 在 mixed GC 時不去考慮它們被填充了多少，而是強制清理所有的老年代，因此也同時清理了從新生代過早提升的對象。這應該會阻止老年代被填滿從而產(chǎn)生一次 full GC。然而，在運行一段時間以后，我們再次驚訝的發(fā)現(xiàn)了一次 full GC。Kirk 推斷說他在其他應用里也見到過這種情況，它是 G1 GC 的一個 bug：mixed GC 顯然沒有清理所有的垃圾，讓它們一直堆積直到產(chǎn)生 full GC。他說他已經(jīng)把這個問題通知了 Oracle，不過他們堅稱我們觀察到的這個現(xiàn)象不是一個 bug，而是正常的。

結論

我們最后做的就是把應用的內存調大了一點點（從 3 GB 到 4 GB），然后 full GC 就消失了。我們仍然觀察到大量的過早提升，不過既然性能是沒問題的，我們就不在乎這些了。一個我們可以嘗試的選項是轉換到 GMS（Concurrent Mark Sweep）GC，不過由于它已經(jīng)被廢棄了，我們還是盡量不去使用它。

那么這個故事的寓意是什么呢？首先，性能問題很容易讓你誤入歧途。一開始看起來是 ZooKeeper 或者 網(wǎng)絡的問題，最后發(fā)現(xiàn)是我們代碼的問題。即使意識到了這一點，我首先采取的措施也沒有考慮周全。為了防止 full GC，我在檢查到底發(fā)生了什么之前就開始調優(yōu) GC。這是一個常見的陷阱，因此記?。杭词鼓阌幸粋€直覺去做什么，先檢查一下到底發(fā)生了什么，再檢查一遍，防止浪費時間去錯誤的問題。

第二條，性能問題太難解決了。我們的代碼有良好的測試覆蓋率，而且運行的特別好，但是它也沒有滿足性能的要求，它在開始的時候就沒有清晰的定義好。性能問題直到部署之后很久才浮現(xiàn)出來。由于通常很難真實的再現(xiàn)你的生產(chǎn)環(huán)境，你經(jīng)常被迫在生產(chǎn)環(huán)境測試性能，即使那聽起來非常糟糕。

第三條，解決一個問題有可能引發(fā)另一個潛在問題的浮現(xiàn)，強迫你不斷挖的比你預想的更深。我們沒有背壓的事實足以中斷這個系統(tǒng)，但是直到我們解決了內存泄漏的問題后，它才浮現(xiàn)。

感謝各位的閱讀！關于“Java內存泄漏排查過程的示例分析”這篇文章就分享到這里了，希望以上內容可以對大家有一定的幫助，讓大家可以學到更多知識，如果覺得文章不錯，可以把它分享出去讓更多的人看到吧！