人人都會(huì)犯錯(cuò)，但一些錯(cuò)誤是如此的荒謬，我想不通怎么會(huì)有人犯這種錯(cuò)誤。更沒(méi)想到的是，這種事竟發(fā)生在了我們身上。當(dāng)然，這種東西只有事后才能發(fā)現(xiàn)真相。接下來(lái)，我將講述一系列最近在我們一個(gè)應(yīng)用上犯過(guò)的這種錯(cuò)誤。最有意思的是，一開(kāi)始的跡象揭示的問(wèn)題，與實(shí)際發(fā)生的問(wèn)題完全不同。

在一個(gè)凄涼的午夜

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

一定是網(wǎng)絡(luò)的問(wèn)題

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

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

ZooKeeper 團(tuán)隊(duì)的同事回復(fù)我了，在他看來(lái)，系統(tǒng)運(yùn)行一切正常。由于其他用戶(hù)看起來(lái)沒(méi)有受到影響，我慢慢意識(shí)到不是 ZooKeeper 的問(wèn)題。日志里明顯是網(wǎng)絡(luò)超時(shí)，于是我把負(fù)責(zé)網(wǎng)絡(luò)的同事叫醒了。

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

一定是 GC 的問(wèn)題

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

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

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

知道原因之后，問(wèn)題就解決一半了，因此我相信這個(gè)問(wèn)題很快就能解決。為了解釋后面的推理，我需要說(shuō)明一下 Adventory 是如何工作的，它不像你們那種標(biāo)準(zhǔn)的微服務(wù)。

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

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

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

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

一定是內(nèi)存泄漏

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

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

真有這么糟糕嗎？

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

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

還是不行

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

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

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

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

這個(gè)模式我在解決性能問(wèn)題時(shí)見(jiàn)過(guò)很多次了：解決一個(gè)問(wèn)題時(shí)會(huì)浮現(xiàn)另一個(gè)你甚至沒(méi)有聽(tīng)說(shuō)過(guò)的問(wèn)題，因?yàn)槠渌麊?wèn)題把它隱藏起來(lái)了。如果你的房子經(jīng)常被淹，你不會(huì)注意到它有火災(zāi)隱患。

修復(fù)由修復(fù)引起的問(wèn)題

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

有了這個(gè)改動(dòng)之后，我們把堆從 12 GB 減少到了 3 GB ，同時(shí)讓系統(tǒng)保持和之前同樣的速度。我們?nèi)匀幻扛魯?shù)小時(shí)就會(huì)有一次暫停長(zhǎng)達(dá) 2 秒的 full GC，不過(guò)這比我們之前見(jiàn)到的 20 秒的暫停（還有系統(tǒng)崩潰）要好多了。

再次優(yōu)化 GC

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

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

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

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

結(jié)論

我們最后做的就是把應(yīng)用的內(nèi)存調(diào)大了一點(diǎn)點(diǎn)（從 3 GB 到 4 GB），然后 full GC 就消失了。我們?nèi)匀挥^察到大量的過(guò)早提升，不過(guò)既然性能是沒(méi)問(wèn)題的，我們就不在乎這些了。一個(gè)我們可以嘗試的選項(xiàng)是轉(zhuǎn)換到 GMS（Concurrent Mark Sweep）GC，不過(guò)由于它已經(jīng)被廢棄了，我們還是盡量不去使用它。

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

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

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

總結(jié)

以上是生活随笔為你收集整理的一次 Java 内存泄漏排查过程，学习学习的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。