歡迎光臨
每天分享高質量文章

一次 Java 記憶體洩漏除錯的有趣經歷

(點選上方公眾號,可快速關註)


來源:ImportNew – yizhe

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

在一個悽涼的午夜

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

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

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

【關於投稿】


如果大家有原創好文投稿,請直接給公號傳送留言。


① 留言格式:
【投稿】+《 文章標題》+ 文章連結

② 示例:
【投稿】《不要自稱是程式員,我十多年的 IT 職場總結》:http://blog.jobbole.com/94148/

③ 最後請附上您的個人簡介哈~



看完本文有收穫?請轉發分享給更多人

關註「ImportNew」,提升Java技能

贊(0)

分享創造快樂