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

在一個淒涼的午夜

午夜剛過，我就被一條來自監控系統的警報吵醒了。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。這是一個常見的陷阱，因此記住：即使你有一個直覺去做什麼，先檢查一下到底發生了什麼，再檢查一遍，防止浪費時間去錯誤的問題。

第二條，效能問題太難解決了。我們的程式碼有良好的測試覆蓋率，而且執行的特別好，但是它也沒有滿足效能的要求，它在開始的時候就沒有清晰的定義好。效能問題直到部署之後很久才浮現出來。由於通常很難真實的再現你的生產環境，你經常被迫在生產環境測試效能，即使那聽起來非常糟糕。

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

歡迎工作一到五年的Java工程師朋友們加入Java填坑之路：860113481

群內提供免費的Java架構學習資料（裡面有高可用、高併發、高效能及分散式、Jvm效能調優、Spring原始碼，MyBatis，Netty,Redis,Kafka,Mysql,Zookeeper,Tomcat,Docker,Dubbo,Nginx等多個知識點的架構資料）合理利用自己每一分每一秒的時間來學習提升自己，不要再用"沒有時間“來掩飾自己思想上的懶惰！趁年輕，使勁拼，給未來的自己一個交代！

一次 Java 記憶體洩漏排查過程，漲姿勢

相關文章