人人都會犯錯，但一些錯誤是如此的荒謬，我想不通怎么會有人犯這種錯誤。更沒想到的是，這種事竟發生在了我們身上。

當然，這種東西只有事后才能發現真相。

接下來，我將講述一系列最近在我們一個應用上犯過的這種錯誤。最有意思的是，一開始的跡象揭示的問題，與實際發生的問題完全不同。

[[243675]]

在一個凄涼的午夜

午夜剛過，我就被一條來自監控系統的警報吵醒了。

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。

這是一個常見的陷阱，因此記住：即使你有一個直覺去做什么，先檢查一下到底發生了什么，再檢查一遍，防止浪費時間去錯誤的問題。

第二條，性能問題太難解決了。我們的代碼有良好的測試覆蓋率，而且運行的特別好，但是它也沒有滿足性能的要求，它在開始的時候就沒有清晰的定義好。

性能問題直到部署之后很久才浮現出來。由于通常很難真實的再現你的生產環境，你經常被迫在生產環境測試性能，即使那聽起來非常糟糕。

第三條，解決一個問題有可能引發另一個潛在問題的浮現，強迫你不斷挖的比你預想的更深。

我們沒有背壓的事實足以中斷這個系統，但是直到我們解決了內存泄漏的問題后，它才浮現。