一次Java內存泄漏調試的有趣經歷

人人都會犯錯，但一些錯誤是如此的荒謬，我想不通怎麼會有人犯這種錯誤。更沒想到的是，這種事竟發生在了咱們身上。固然，這種東西只有過後才能發現真相。接下來，我將講述一系列最近在咱們一個應用上犯過的這種錯誤。最有意思的是，一開始的跡象揭示的問題，與實際發生的問題徹底不一樣。

在一個淒涼的午夜

午夜剛過，我就被一條來自監控系統的警報吵醒了。Adventory，咱們的 PPC （以點擊次數收費）廣告系統中一個負責索引廣告的應用，很明顯連續重啓了好幾回。在雲端的環境裏，實例的重啓是很正常的，也不會觸發報警，但此次實例重啓的次數在短期內超過了閾值。我打開了筆記本電腦，一頭扎進項目的日誌裏。

必定是網絡的問題

我看到服務在鏈接 ZooKeeper 時發生了數次超時。咱們使用 ZooKeeper（ZK）協調多個實例間的索引操做，並依賴它實現魯棒性。很顯然，一次 Zookeeper 失敗會阻止索引操做的繼續運行，不過它應該不會致使整個系統掛掉。並且，這種狀況很是罕見（這是我第一次遇到 ZK 在生產環境掛掉），我以爲這個問題可能不太容易搞定。因而我把 ZooKeeper 的值班人員喊醒了，讓他們看看發生了什麼。

同時，我檢查了咱們的配置，發現 ZooKeeper 鏈接的超時時間是秒級的。很明顯，ZooKeeper 全掛了，因爲其餘服務也在使用它，這意味着問題很是嚴重。我給其餘幾個團隊發了消息，他們顯然還不知道這事兒。

ZooKeeper 團隊的同事回覆我了，在他看來，系統運行一切正常。因爲其餘用戶看起來沒有受到影響，我慢慢意識到不是 ZooKeeper 的問題。日誌裏明顯是網絡超時，因而我把負責網絡的同事叫醒了。

負責網絡的團隊檢查了他們的監控，沒有發現任何異常。因爲單個網段，甚至單個節點，都有可能和剩餘的其餘節點斷開鏈接，他們檢查了咱們系統實例所在的幾臺機器，沒有發現異常。其間，我嘗試了其餘幾種思路，不過都行不通，我也到了本身智力的極限。時間已經很晚了（或者說很早了），同時，跟個人嘗試沒有任何關係，重啓變得不那麼頻繁了。因爲這個服務僅僅負責數據的刷新，並不會影響到數據的可用性，咱們決定把問題放到上午再說。

必定是 GC 的問題

有時候把難題放一放，睡一覺，等腦子清醒了再去解決是一個好主意。沒人知道當時發生了什麼，服務表現的很是怪異。忽然間，我想到了什麼。Java 服務表現怪異的主要根源是什麼？固然是垃圾回收。

爲了應對目前這種狀況的發生，咱們一直打印着 GC 的日誌。我立刻把 GC 日誌下載了下來，而後打開 Censum開始分析日誌。我還沒仔細看，就發現了一個恐怖的狀況：每15分鐘發生一次 full GC，每次 GC 引起長達 20 秒的服務停頓。怪不得鏈接 ZooKeeper 超時了，即便 ZooKeeper 和網絡都沒有問題。

這些停頓也解釋了爲何整個服務一直是死掉的，而不是超時以後只打一條錯誤日誌。咱們的服務運行在 Marathon 上，它定時檢查每一個實例的健康狀態，若是某個端點在一段時間內沒有響應，Marathon 就重啓那個服務。

知道緣由以後，問題就解決一半了，所以我相信這個問題很快就能解決。爲了解釋後面的推理，我須要說明一下 Adventory 是如何工做的，它不像大家那種標準的微服務。

Adventory 是用來把咱們的廣告索引到 ElasticSearch (ES) 的。這須要兩個步驟。第一步是獲取所需的數據。到目前爲止，這個服務從其餘幾個系統中接收經過 Hermes 發來的事件。數據保存到 MongoDB 集羣中。數據量最多每秒幾百個請求，每一個操做都特別輕量，所以即使觸發一些內存的回收，也耗費不了多少資源。第二步就是數據的索引。這個操做定時執行（大概兩分鐘執行一次），把全部 MongoDB 集羣存儲的數據經過 RxJava 收集到一個流中，組合爲非範式的記錄，發送給 ElasticSearch。這部分操做相似離線的批處理任務，而不是一個服務。

因爲常常須要對數據作大量的更新，維護索引就不太值得，因此每執行一次定時任務，整個索引都會重建一次。這意味着一整塊數據都要通過這個系統，從而引起大量的內存回收。儘管使用了流的方式，咱們也被迫把堆加到了 12 GB 這麼大。因爲堆是如此巨大（並且目前被全力支持），咱們的 GC 選擇了 G1。

我之前處理過的服務中，也會回收大量生命週期很短的對象。有了那些經驗，我同時增長了 -XX:G1NewSizePercent 和 -XX:G1MaxNewSizePercent 的默認值，這樣新生代會變得更大，young GC 就能夠處理更多的數據，而不用把它們送到老年代。Censum 也顯示有不少過早提高。這和一段時間以後發生的 full GC 也是一致的。不幸的是，這些設置沒有起到任何做用。

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

必定是內存泄漏

這時，一個當時頭腦還保持冷靜的同事，建議咱們應該作一開始就作的事情：檢查堆中的數據。咱們準備了一個開發環境的實例，擁有和線上實例相同的數據量，堆的大小也大體相同。把它鏈接到 jnisualvm ，分析內存的樣本，咱們能夠看到堆中對象的大體數量和大小。大眼一看，能夠發現咱們域中Ad對象的數量高的不正常，而且在索引的過程當中一直在增加，一直增加到咱們處理的廣告的數量級別。可是……這不該該啊。畢竟，咱們經過 RX 把這些數據整理成流，就是爲了防止把全部的數據都加載到內存裏。

隨着懷疑愈來愈強，我檢查了這部分代碼。它們是兩年前寫的，以後就沒有再被仔細的檢查過。果不其然，咱們實際上把全部的數據都加載到了內存裏。這固然不是故意的。因爲當時對 RxJava 的理解不夠全面，咱們想讓代碼以一種特殊的方式並行運行。爲了從 RX 的主工做流中剝離出來一些工做，咱們決定用一個單獨的 executor 跑 CompetableFuture。可是，咱們所以就須要等待全部的 CompetableFuture 都工做完……經過存儲他們的引用，而後調用 join()。這致使一直到索引完成，全部的 future 的引用，以及它們引用到的數據，都保持着生存的狀態。這阻止了垃圾收集器及時的把它們清理掉。

真有這麼糟糕嗎？

固然這是一個很愚蠢的錯誤，對於發現得這麼晚，咱們也很噁心。我甚至想起好久以前，關於這個應用須要 12 GB 的堆的問題，曾有個簡短的討論。12 GB 的堆，確實有點大了。可是另外一方面，這些代碼已經運行了將近兩年了，沒有發生過任何問題。咱們能夠在當時相對容易的修復它，然而若是是兩年前，這可能須要咱們花費更多的時間，並且相對於節省幾個 G 的內存，當時咱們有不少更重要的工做。

所以，雖然從純技術的角度來講，這個問題如此長時間沒解決確實很丟人，然而從戰略性的角度來看，或許留着這個浪費內存的問題無論，是更務實的選擇。固然，另外一個考慮就是這個問題一旦發生，會形成什麼影響。咱們幾乎沒有對用戶形成任何影響，不過結果有可能更糟糕。軟件工程就是權衡利弊，決定不一樣任務的優先級也不例外。

仍是不行

有了更多使用 RX 的經驗以後，咱們能夠很簡單的解決 ComplerableFurue 的問題。重寫代碼，只使用 RX；在重寫的過程當中，升級到 RX2；真正的流式處理數據，而不是在內存裏收集它們。這些改動經過 code review 以後，部署到開發環境進行測試。讓咱們吃驚的是，應用所需的內存絲毫沒有減小。內存抽樣顯示，相較以前，內存中廣告對象的數量有所減小。並且對象的數量如今不會一直增加，有時也會降低，所以他們不是所有在內存裏收集的。仍是老問題，看起來這些數據仍然沒有真正的被歸集成流。

那如今是怎麼回事？

相關的關鍵詞剛纔已經提到了：背壓。當數據被流式處理，生產者和消費者的速度不一樣是很正常的。若是生產者比消費者快，而且不能把速度降下來，它就會一直生產愈來愈多的數據，消費者沒法以一樣的速度處理掉他們。現象就是未處理數據的緩存不斷增加，而這就是咱們應用中真正發生的。背壓就是一套機制，它容許一個較慢的消費者告訴較快的生產者去降速。

咱們的索引系統沒有背壓的概念，這在以前沒什麼問題，反正咱們把整個索引都保存到內存裏了。一旦咱們解決了以前的問題，開始真正的流式處理數據，缺乏背壓的問題就變得很明顯了。

這個模式我在解決性能問題時見過不少次了：解決一個問題時會浮現另外一個你甚至沒有據說過的問題，由於其餘問題把它隱藏起來了。若是你的房子常常被淹，你不會注意到它有火災隱患。

修復由修復引發的問題

在 RxJava 2 裏，原來的 Observable 類被拆成了不支持背壓的 Observable 和支持背壓的 Flowable。幸運的是，有一些簡單的辦法，能夠開箱即用的把不支持背壓的 Observable 改形成支持背壓的 Flowable。其中包含從非響應式的資源好比 Iterable 建立 Flowable。把這些 Flowable 融合起來能夠生成一樣支持背壓的 Flowable，所以只要快速解決一個點，整個系統就有了背壓的支持。

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

再次優化 GC

可是，故事到此尚未結束。檢查 GC 的日誌，咱們注意到大量的過早提高，佔到 70%。儘管性能已經能夠接受了，咱們也嘗試去解決這個問題，但願也許能夠同時解決 full GC 的問題。

 

若是一個對象的生命週期很短，可是它仍然晉升到了老年代，咱們就把這種現象叫作過早提高（premature tenuring）（或者叫過早升級）。老年代裏的對象一般都比較大，使用與新生代不一樣的 GC 算法，而這些過早提高的對象佔據了老年代的空間，因此它們會影響 GC 的性能。所以，咱們想竭力避免過早提高。

咱們的應用在索引的過程當中會產生大量短生命週期的對象，所以一些過早提高是正常的，可是不該該如此嚴重。當應用產生大量短生命週期的對象時，能想到的第一件事就是簡單的增長新生代的空間。默認狀況下，G1 的 GC 能夠自動的調整新生代的空間，容許新生代使用堆內存的 5% 至 60%。我注意到運行的應用裏，新生代和老年代的比例一直在一個很寬的幅度裏變化，不過我依然動手修改了兩個參數：-XX:G1NewSizePercent=40 和 -XX:G1MaxNewSizePercent=90看看會發生什麼。這沒起做用，甚至讓事情變得更糟糕了，應用一啓動就觸發了 full GC。我也嘗試了其餘的比例，不過最好的狀況就是隻增長 G1MaxNewSizePercent而不修改最小值。這起了做用，大概和默認值的表現差很少，也沒有變好。

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

結論

咱們最後作的就是把應用的內存調大了一點點（從 3 GB 到 4 GB），而後 full GC 就消失了。咱們仍然觀察到大量的過早提高，不過既然性能是沒問題的，咱們就不在意這些了。一個咱們能夠嘗試的選項是轉換到 GMS（Concurrent Mark Sweep）GC，不過因爲它已經被廢棄了，咱們仍是儘可能不去使用它。

 

那麼這個故事的寓意是什麼呢？首先，性能問題很容易讓你誤入歧途。一開始看起來是 ZooKeeper 或者 網絡的問題，最後發現是咱們代碼的問題。即便意識到了這一點，我首先採起的措施也沒有考慮周全。爲了防止 full GC，我在檢查到底發生了什麼以前就開始調優 GC。這是一個常見的陷阱，所以記住：即便你有一個直覺去作什麼，先檢查一下到底發生了什麼，再檢查一遍，防止浪費時間去錯誤的問題。

第二條，性能問題太難解決了。咱們的代碼有良好的測試覆蓋率，並且運行的特別好，可是它也沒有知足性能的要求，它在開始的時候就沒有清晰的定義好。性能問題直到部署以後好久才浮現出來。因爲一般很難真實的再現你的生產環境，你常常被迫在生產環境測試性能，即便那聽起來很是糟糕。

第三條，解決一個問題有可能引起另外一個潛在問題的浮現，強迫你不斷挖的比你預想的更深。咱們沒有背壓的事實足以中斷這個系統，可是直到咱們解決了內存泄漏的問題後，它才浮現。

我但願咱們這個有趣的經歷，能在你解決本身遇到的性能問題時發揮一些做用。

原文連接： allegro.tech 翻譯： ImportNew.com - yizhe

譯文連接： http://www.importnew.com/29591.html