Java 內(nèi)存泄漏調(diào)試錯誤怎么辦?Adventory，我們的 PPC
(以點(diǎn)擊次數(shù)收費(fèi))廣告系統(tǒng)中一個負(fù)責(zé)索引廣告的應(yīng)用，很明顯連續(xù)重啟了好幾次。在云端的環(huán)境里，實(shí)例的重啟是很正常的，也不會觸發(fā)報(bào)警，但這次實(shí)例重啟的次數(shù)在短時間內(nèi)超過了閾值。我打開了筆記本電腦，一頭扎進(jìn)項(xiàng)目的日志里。
Java 內(nèi)存泄漏調(diào)試錯誤怎么辦?一定是網(wǎng)絡(luò)的問題
我看到服務(wù)在連接 ZooKeeper 時發(fā)生了數(shù)次超時。我們使用 ZooKeeper(ZK)協(xié)調(diào)多個實(shí)例間的索引操作，并依賴它實(shí)現(xiàn)魯棒性。很顯然，一次
Zookeeper 失敗會阻止索引操作的繼續(xù)運(yùn)行，不過它應(yīng)該不會導(dǎo)致整個系統(tǒng)掛掉。而且，這種情況非常罕見(這是我第一次遇到 ZK
在生產(chǎn)環(huán)境掛掉)，我覺得這個問題可能不太容易搞定。于是我把 ZooKeeper 的值班人員喊醒了，讓他們看看發(fā)生了什么。
同時，我檢查了我們的配置，發(fā)現(xiàn) ZooKeeper 連接的超時時間是秒級的。很明顯，ZooKeeper
全掛了，由于其他服務(wù)也在使用它，這意味著問題非常嚴(yán)重。我給其他幾個團(tuán)隊(duì)發(fā)了消息，他們顯然還不知道這事兒。
ZooKeeper 團(tuán)隊(duì)的同事回復(fù)我了，在他看來，系統(tǒng)運(yùn)行一切正常。由于其他用戶看起來沒有受到影響，我慢慢意識到不是 ZooKeeper
的問題。日志里明顯是網(wǎng)絡(luò)超時，于是我把負(fù)責(zé)網(wǎng)絡(luò)的同事叫醒了。
負(fù)責(zé)網(wǎng)絡(luò)的團(tuán)隊(duì)檢查了他們的監(jiān)控，沒有發(fā)現(xiàn)任何異常。由于單個網(wǎng)段，甚至單個節(jié)點(diǎn)，都有可能和剩余的其他節(jié)點(diǎn)斷開連接，他們檢查了我們系統(tǒng)實(shí)例所在的幾臺機(jī)器，沒有發(fā)現(xiàn)異常。其間，我嘗試了其他幾種思路，不過都行不通，我也到了自己智力的極限。
時間已經(jīng)很晚了(或者說很早了)，同時，跟我的嘗試沒有任何關(guān)系，重啟變得不那么頻繁了。由于這個服務(wù)僅僅負(fù)責(zé)數(shù)據(jù)的刷新，并不會影響到數(shù)據(jù)的可用性，我們決定把問題放到上午再說。
Java 內(nèi)存泄漏調(diào)試錯誤怎么辦?一定是 GC 的問題
有時候把難題放一放，睡一覺，等腦子清醒了再去解決是一個好主意。沒人知道當(dāng)時發(fā)生了什么，服務(wù)表現(xiàn)的非常怪異。突然間，我想到了什么。Java
服務(wù)表現(xiàn)怪異的主要根源是什么?當(dāng)然是垃圾回收。
為了應(yīng)對目前這種情況的發(fā)生，我們一直打印著 GC 的日志。我馬上把 GC 日志下載了下來，然后打開
Censum開始分析日志。我還沒仔細(xì)看，就發(fā)現(xiàn)了一個恐怖的情況：每15分鐘發(fā)生一次 full GC，每次 GC 引發(fā)長達(dá) 20 秒的服務(wù)停頓。怪不得連接
ZooKeeper 超時了，即使 ZooKeeper 和網(wǎng)絡(luò)都沒有問題。
這些停頓也解釋了為什么整個服務(wù)一直是死掉的，而不是超時之后只打一條錯誤日志。我們的服務(wù)運(yùn)行在 Marathon
上，它定時檢查每個實(shí)例的健康狀態(tài)，如果某個端點(diǎn)在一段時間內(nèi)沒有響應(yīng)，Marathon 就重啟那個服務(wù)。
知道原因之后，問題就解決一半了，因此我相信這個問題很快就能解決。為了解釋后面的推理，我需要說明一下 Adventory
是如何工作的，它不像你們那種標(biāo)準(zhǔn)的微服務(wù)。
Adventory 是用來把我們的廣告索引到 ElasticSearch (ES)
的。這需要兩個步驟。第一步是獲取所需的數(shù)據(jù)。到目前為止，這個服務(wù)從其他幾個系統(tǒng)中接收通過 Hermes 發(fā)來的事件。數(shù)據(jù)保存到 MongoDB 集群中。
數(shù)據(jù)量最多每秒幾百個請求，每個操作都特別輕量，因此即便觸發(fā)一些內(nèi)存的回收，也耗費(fèi)不了多少資源。第二步就是數(shù)據(jù)的索引。這個操作定時執(zhí)行(大概兩分鐘執(zhí)行一次)，把所有
MongoDB 集群存儲的數(shù)據(jù)通過 RxJava 收集到一個流中，組合為非范式的記錄，發(fā)送給
ElasticSearch。這部分操作類似離線的批處理任務(wù)，而不是一個服務(wù)。
由于經(jīng)常需要對數(shù)據(jù)做大量的更新，維護(hù)索引就不太值得，所以每執(zhí)行一次定時任務(wù)，整個索引都會重建一次。這意味著一整塊數(shù)據(jù)都要經(jīng)過這個系統(tǒng)，從而引發(fā)大量的內(nèi)存回收。盡管使用了流的方式，我們也被迫把堆加到了
12 GB 這么大。由于堆是如此巨大(而且目前被全力支持)，我們的 GC 選擇了 G1。
我以前處理過的服務(wù)中，也會回收大量生命周期很短的對象。有了那些經(jīng)驗(yàn)，我同時增加了 -XX:G1NewSizePercent 和
-XX:G1MaxNewSizePercent 的默認(rèn)值，這樣新生代會變得更大，young GC 就可以處理更多的數(shù)據(jù)，而不用把它們送到老年代。Censum
也顯示有很多過早提升。這和一段時間之后發(fā)生的 full GC 也是一致的。不幸的是，這些設(shè)置沒有起到任何作用。
接下來我想，或許生產(chǎn)者制造數(shù)據(jù)太快了，消費(fèi)者來不及消費(fèi)，導(dǎo)致這些記錄在它們被處理前就被回收了。我嘗試減小生產(chǎn)數(shù)據(jù)的線程數(shù)量，降低數(shù)據(jù)產(chǎn)生的速度，同時保持消費(fèi)者發(fā)送給
ES 的數(shù)據(jù)池大小不變。這主要是使用背壓(backpressure)機(jī)制，不過它也沒有起到作用。
一定是內(nèi)存泄漏
這時，一個當(dāng)時頭腦還保持冷靜的同事，建議我們應(yīng)該做一開始就做的事情：檢查堆中的數(shù)據(jù)。我們準(zhǔn)備了一個開發(fā)環(huán)境的實(shí)例，擁有和線上實(shí)例相同的數(shù)據(jù)量，堆的大小也大致相同。把它連接到
jnisualvm ，分析內(nèi)存的樣本，我們可以看到堆中對象的大致數(shù)量和大小。
打眼一看，可以發(fā)現(xiàn)我們域中Ad對象的數(shù)量高的不正常，并且在索引的過程中一直在增長，一直增長到我們處理的廣告的數(shù)量級別。但是……這不應(yīng)該啊。畢竟，我們通過
RX 把這些數(shù)據(jù)整理成流，就是為了防止把所有的數(shù)據(jù)都加載到內(nèi)存里。
隨著懷疑越來越強(qiáng)，我檢查了這部分代碼。它們是兩年前寫的，之后就沒有再被仔細(xì)的檢查過。果不其然，我們實(shí)際上把所有的數(shù)據(jù)都加載到了內(nèi)存里。這當(dāng)然不是故意的。由于當(dāng)時對
RxJava 的理解不夠全面，我們想讓代碼以一種特殊的方式并行運(yùn)行。為了從 RX 的主工作流中剝離出來一些工作，我們決定用一個單獨(dú)的 executor 跑
CompetableFuture。
但是，我們因此就需要等待所有的 CompetableFuture 都工作完……通過存儲他們的引用，然后調(diào)用 join()。這導(dǎo)致一直到索引完成，所有的
future 的引用，以及它們引用到的數(shù)據(jù)，都保持著生存的狀態(tài)。這阻止了垃圾收集器及時的把它們清理掉。
真有這么糟糕嗎?
當(dāng)然這是一個很愚蠢的錯誤，對于發(fā)現(xiàn)得這么晚，我們也很惡心。我甚至想起很久之前，關(guān)于這個應(yīng)用需要 12 GB 的堆的問題，曾有個簡短的討論。12 GB
的堆，確實(shí)有點(diǎn)大了。
但是另一方面，這些代碼已經(jīng)運(yùn)行了將近兩年了，沒有發(fā)生過任何問題。我們可以在當(dāng)時相對容易的修復(fù)它，然而如果是兩年前，這可能需要我們花費(fèi)更多的時間，而且相對于節(jié)省幾個
G 的內(nèi)存，當(dāng)時我們有很多更重要的工作。
因此，雖然從純技術(shù)的角度來說，這個問題如此長時間沒解決確實(shí)很丟人，然而從戰(zhàn)略性的角度來看，或許留著這個浪費(fèi)內(nèi)存的問題不管，是更務(wù)實(shí)的選擇。當(dāng)然，另一個考慮就是這個問題一旦發(fā)生，會造成什么影響。我們幾乎沒有對用戶造成任何影響，不過結(jié)果有可能更糟糕。軟件工程就是權(quán)衡利弊，決定不同任務(wù)的優(yōu)先級也不例外。
還是不行
有了更多使用 RX 的經(jīng)驗(yàn)之后，我們可以很簡單的解決 ComplerableFurue 的問題。重寫代碼，只使用 RX;在重寫的過程中，升級到
RX2;真正的流式處理數(shù)據(jù)，而不是在內(nèi)存里收集它們。這些改動通過 code review
之后，部署到開發(fā)環(huán)境進(jìn)行測試。讓我們吃驚的是，應(yīng)用所需的內(nèi)存絲毫沒有減少。
內(nèi)存抽樣顯示，相較之前，內(nèi)存中廣告對象的數(shù)量有所減少。而且對象的數(shù)量現(xiàn)在不會一直增長，有時也會下降，因此他們不是全部在內(nèi)存里收集的。還是老問題，看起來這些數(shù)據(jù)仍然沒有真正的被歸集成流。
那現(xiàn)在是怎么回事?
相關(guān)的關(guān)鍵詞剛才已經(jīng)提到了：背壓。當(dāng)數(shù)據(jù)被流式處理，生產(chǎn)者和消費(fèi)者的速度不同是很正常的。如果生產(chǎn)者比消費(fèi)者快，并且不能把速度降下來，它就會一直生產(chǎn)越來越多的數(shù)據(jù)，消費(fèi)者無法以同樣的速度處理掉他們?，F(xiàn)象就是未處理數(shù)據(jù)的緩存不斷增長，而這就是我們應(yīng)用中真正發(fā)生的。背壓就是一套機(jī)制，它允許一個較慢的消費(fèi)者告訴較快的生產(chǎn)者去降速。
我們的索引系統(tǒng)沒有背壓的概念，這在之前沒什么問題，反正我們把整個索引都保存到內(nèi)存里了。一旦我們解決了之前的問題，開始真正的流式處理數(shù)據(jù)，缺少背壓的問題就變得很明顯了。
這個模式我在解決性能問題時見過很多次了：解決一個問題時會浮現(xiàn)另一個你甚至沒有聽說過的問題，因?yàn)槠渌麊栴}把它隱藏起來了。如果你的房子經(jīng)常被淹，你不會注意到它有火災(zāi)隱患。
修復(fù)由修復(fù)引起的問題
在 RxJava 2 里，原來的 Observable 類被拆成了不支持背壓的 Observable 和支持背壓的
Flowable。幸運(yùn)的是，有一些簡單的辦法，可以開箱即用的把不支持背壓的 Observable 改造成支持背壓的
Flowable。其中包含從非響應(yīng)式的資源比如 Iterable 創(chuàng)建 Flowable。把這些 Flowable 融合起來可以生成同樣支持背壓的
Flowable，因此只要快速解決一個點(diǎn)，整個系統(tǒng)就有了背壓的支持。
有了這個改動之后，我們把堆從 12 GB 減少到了 3 GB ，同時讓系統(tǒng)保持和之前同樣的速度。我們?nèi)匀幻扛魯?shù)小時就會有一次暫停長達(dá) 2 秒的
full GC，不過這比我們之前見到的 20 秒的暫停(還有系統(tǒng)崩潰)要好多了。
再次優(yōu)化 GC
但是，故事到此還沒有結(jié)束。檢查 GC 的日志，我們注意到大量的過早提升，占到
70%。盡管性能已經(jīng)可以接受了，我們也嘗試去解決這個問題，希望也許可以同時解決 full GC 的問題。
如果一個對象的生命周期很短，但是它仍然晉升到了老年代，我們就把這種現(xiàn)象叫做過早提升(premature
tenuring)(或者叫過早升級)。老年代里的對象通常都比較大，使用與新生代不同的 GC 算法，而這些過早提升的對象占據(jù)了老年代的空間，所以它們會影響 GC
的性能。因此，我們想竭力避免過早提升。
我們的應(yīng)用在索引的過程中會產(chǎn)生大量短生命周期的對象，因此一些過早提升是正常的，但是不應(yīng)該如此嚴(yán)重。當(dāng)應(yīng)用產(chǎn)生大量短生命周期的對象時，能想到的第一件事就是簡單的增加新生代的空間。默認(rèn)情況下，G1
的 GC 可以自動的調(diào)整新生代的空間，允許新生代使用堆內(nèi)存的 5% 至 60%。
我注意到運(yùn)行的應(yīng)用里，新生代和老年代的比例一直在一個很寬的幅度里變化，不過我依然動手修改了兩個參數(shù)：-XX:G1NewSizePercent=40 和
-XX:G1MaxNewSizePercent=90看看會發(fā)生什么。這沒起作用，甚至讓事情變得更糟糕了，應(yīng)用一啟動就觸發(fā)了 full
GC。我也嘗試了其他的比例，不過最好的情況就是只增加
G1MaxNewSizePercent而不修改最小值。這起了作用，大概和默認(rèn)值的表現(xiàn)差不多，也沒有變好。
嘗試了很多辦法后，也沒有取得什么成就，我就放棄了，然后給 Kirk Pepperdine 發(fā)了封郵件。他是位很知名的 Java 性能專家，我碰巧在
Allegro 舉辦的 Devoxx 會議的訓(xùn)練課程里認(rèn)識了他。通過查看 GC 的日志以及幾封郵件的交流，Kirk 建議試試設(shè)置
-XX:G1MixedGCLiveThresholdPercent=100。這個設(shè)置應(yīng)該會強(qiáng)制 G1 GC 在 mixed GC
時不去考慮它們被填充了多少，而是強(qiáng)制清理所有的老年代，因此也同時清理了從新生代過早提升的對象。這應(yīng)該會阻止老年代被填滿從而產(chǎn)生一次 full GC。
然而，在運(yùn)行一段時間以后，我們再次驚訝的發(fā)現(xiàn)了一次 full GC。Kirk 推斷說他在其他應(yīng)用里也見到過這種情況，它是 G1 GC 的一個
bug：mixed GC 顯然沒有清理所有的垃圾，讓它們一直堆積直到產(chǎn)生 full GC。他說他已經(jīng)把這個問題通知了
Oracle，不過他們堅(jiān)稱我們觀察到的這個現(xiàn)象不是一個 bug，而是正常的。
我們最后做的就是把應(yīng)用的內(nèi)存調(diào)大了一點(diǎn)點(diǎn)(從 3 GB 到 4 GB)，然后 full GC
就消失了。我們?nèi)匀挥^察到大量的過早提升，不過既然性能是沒問題的，我們就不在乎這些了。一個我們可以嘗試的選項(xiàng)是轉(zhuǎn)換到 GMS(Concurrent Mark
Sweep)GC，不過由于它已經(jīng)被廢棄了，我們還是盡量不去使用它。
那么這個故事的寓意是什么呢?
首先，性能問題很容易讓你誤入歧途。一開始看起來是 ZooKeeper 或者
網(wǎng)絡(luò)的問題，最后發(fā)現(xiàn)是我們代碼的問題。即使意識到了這一點(diǎn)，我首先采取的措施也沒有考慮周全。為了防止 full GC，我在檢查到底發(fā)生了什么之前就開始調(diào)優(yōu)
GC。這是一個常見的陷阱，因此記?。杭词鼓阌幸粋€直覺去做什么，先檢查一下到底發(fā)生了什么，再檢查一遍，防止浪費(fèi)時間去錯誤的問題。
第二條，性能問題太難解決了。我們的代碼有良好的測試覆蓋率，而且運(yùn)行的特別好，但是它也沒有滿足性能的要求，它在開始的時候就沒有清晰的定義好。性能問題直到部署之后很久才浮現(xiàn)出來。由于通常很難真實(shí)的再現(xiàn)你的生產(chǎn)環(huán)境，你經(jīng)常被迫在生產(chǎn)環(huán)境測試性能，即使那聽起來非常糟糕。
第三條，解決一個問題有可能引發(fā)另一個潛在問題的浮現(xiàn)，強(qiáng)迫你不斷挖的比你預(yù)想的更深。我們沒有背壓的事實(shí)足以中斷這個系統(tǒng)，但是直到我們解決了內(nèi)存泄漏的問題后，它才浮現(xiàn)。
感謝大家閱讀由java問答分享的“Java 內(nèi)存泄漏調(diào)試錯誤怎么辦?”希望對大家有所幫助，想了解更多培訓(xùn)信息請關(guān)注java培訓(xùn)機(jī)構(gòu)官網(wǎng)
免責(zé)聲明：以上內(nèi)容僅作為信息傳播，文中部分信息來源于互聯(lián)網(wǎng)，僅供閱讀參考。
