【大記憶體服務GC實踐】- “ParNew+CMS”實踐案例 （一）- NameNode YGC診斷優化
這是”大記憶體服務GC實踐”的第三篇文章，前面兩篇文章分別系統地介紹了”ParNew+CMS”組合垃圾回收器的原理以及FullGC的一些排查思路。分別見：
本篇文章重點結合生產線上NameNode RPC毛刺這個現象，分析兩起嚴重的YGC問題。NameNode是HDFS服務最核心的元件，大資料任務讀寫檔案都需要請求NameNode，該服務一旦出現RPC處理毛刺，就可能會引起上層大資料平臺離線、實時任務的延遲甚至異常。公司內部NameNode採用”ParNew+CMS”組合垃圾回收器。
案例一 NameNode升級之後RPC大毛刺問題探究
問題背景
隨著HDFS叢集規模的增大，NameNode效能壓力越來越大，因此我們結合社群新版本的優化進行了內部分支的優化併發布上線。上線之後觀察了一週，發現上線後RPC排隊毛刺明顯變大變多。如下圖所示：
問題分析
為什麼RPC排隊毛刺會出現？
按照經驗來看，NameNode的RPC請求處理/排隊毛刺很大有可能有這麼幾個原因：
- 大規模檔案刪除導致NameNode卡住。
- 大目錄getContentSummary介面呼叫。
- 大GC影響。
按照這幾個思路分別檢視監控，發現事發時間點GC表現有些異常，如下所示：
結合時間點檢視對應的GC日誌，發現部分YGC耗時異常。正常情況下YGC耗時基本穩定在0.2～0.5秒，但是事發時間段耗時長達3秒、7秒。如下圖所示：
為什麼YGC耗時卡頓這麼長時間？
這裡面一個最關鍵的資訊點是多次YGC的user和sys耗時都是0.00秒，這說明這段時間根本就沒有發生CPU的消耗。結合經驗，如果user+sys的時間遠小於real的值，這種情況說明JVM暫停的時間沒有消耗在CPU執行上，而大概率卡頓在IO上。觀察對應時間點節點磁碟IO利用率，發現系統盤IO確實被打滿了。如下圖所示：
為什麼系統盤IO會被打滿？
那什麼原因造成系統盤IO打滿的呢？按照以往經驗來說，一般有兩種可能，一種可能是日誌寫入造成，一種可能是快取換入換出造成。經過監控系統的進一步分析，確認這個IO是讀IO，這就否定了日誌寫入這個可能性。如下圖所示：
再結合對應時間段快取換入換出次數的監控，基本可以確認系統盤IO打滿是因為快取大量換入導致。如下圖：
為什麼新版本上線後會頻繁觸發快取換入呢?
經過進一步分析發現，這個節點上有一個指令碼會週期性判斷系統pagecache使用量是否超過一個閾值，如果超過的話就會執行清理操作。我們知道pagecache是用來快取檔案的，如果執行pagecache清理的話可能會導致短時間讀檔案都需要從磁碟上讀，進而導致讀IO增大。
那為什麼新版本上線後會頻繁觸發這個問題呢？經過線下驗證，NameNode新版本中部分新引入的功能會頻繁讀寫日誌檔案，導致節點pagecache消耗非常快。這樣就會更加頻繁的觸發指令碼清理cache。
案例二. Ranger外掛升級之後NameNode RPC大毛刺問題探究
問題背景
這個案例是NameNode的Ranger外掛升級之後產生的，所以有必有先介紹一下 Apache Ranger 。Ranger是Hadoop生態中各種元件許可權\審計管控的服務。比如HDFS，使用者讀取一個檔案的話首先需要經過Ranger的鑑權認證的，如果許可權認證成功，才能進行讀取操作，否則就會報認證異常。
從技術層面看，使用者讀取HDFS檔案首先會向NameNode傳送一個讀取請求，NameNode服務本身集成了一個Ranger外掛，這個Ranger外掛負責從Ranger Server拉取許可權庫資訊到本地快取，同時通過hook的方式監聽NameNode讀取請求，一旦有讀取請求，Ranger外掛攔截到使用者資訊以及檔案路徑資訊，再根據許可權庫中資訊進行匹配，如果能夠匹配上就認證成功。
有了Ranger這個背景之後，再來看這個案例。生產線上一Ranger外掛升級後，第二天檢視主NameNode，發現請求處理RPC耗時出現較頻繁的毛刺，平均請求處理耗時相比升級前也增加了60%+。如下圖所示，其中hadoop3897是升級前的NameNode，平均請求處理耗時為18ms，Ranger升級後主NameNode切換到hadoop3898，平均請求處理耗時為33ms。很明顯，升級後主NameNode頻繁出現超過1s的請求處理毛刺。
問題分析
為什麼PRC處理毛刺會出現？
NameNode切換到hadoop3898節點後出現請求處理毛刺這個現象在之前也出現過，當時猜測和機器本身有關係。為了排除這個因素，運維將主NameNode切換到hadoop3897節點（也已經升級過Ranger外掛），切換後發現還是存在嚴重的效能問題。這種情況就不排除是因為Ranger升級之後引入的效能問題。
排查異常NameNode相關指標發現一個非常關鍵的線索，每分鐘GC時間在升級之後出現明顯增多，如下圖所示：
為了更細節地明確GC問題，檢視相關的GC日誌，發現兩個重要事實：
-
升級後YGC的頻率從平均20s一次增多到10s一次左右，而且可能會出現連續多次YGC耗時都超過1～2s的情況，對比升級前每次YGC耗時基本穩定在0.5s左右。
Desired survivor size 5368709120 bytes, new threshold 15 (max 15) - age 1: 845855096 bytes, 845855096 total - age 2: 315664752 bytes, 1161519848 total - age 3: 6367320 bytes, 1167887168 total - age 4: 389355792 bytes, 1557242960 total - age 5: 9163192 bytes, 1566406152 total - age 6: 37404216 bytes, 1603810368 total - age 7: 930872 bytes, 1604741240 total - age 12: 96928 bytes, 1604838168 total - age 15: 3352 bytes, 1604841520 total : 42842835K->1874036K(52428800K), 3.3199043 secs] 458215362K->417246566K(618659840K), 3.3203978 secs] [Times: user=15.94 sys=3.41, real=3.32 secs]
2. 升級後CMS GC執行remark階段耗時太長，會造成NameNode長達90秒的卡頓。
2021-11-17T18:33:09.820+0800: 179227.136: [Rescan (parallel) , 0.4236529 secs] 2021-11-17T18:33:10.244+0800: 179227.560: [weak refs processing, 93.3276296 secs] 2021-11-17T18:34:43.571+0800: 179320.888: [class unloading, 0.0895056 secs] 2021-11-17T18:34:43.661+0800: 179320.977: [scrub symbol table, 0.0107147 secs] 2021-11-17T18:34:43.671+0800: 179320.988: [scrub string table, 0.0025554 secs] [1 CMS-remark: 415575980K(566231040K)] 416281199K(618659840K), 94.1390159 secs] [Times: user=107.70 sys=10.29, real=94.14 secs]
至此基本可以確認NameNode請求延遲毛刺是因為Ranger升級之後導致NameNode程序YGC頻率增多，且單次耗時增多導致。
為什麼YGC和CMS GC Remark耗時變長了呢？
這裡面最關鍵的一個線索來自於CMS GC Remark日誌，如下所示：
... 2021-11-17T18:33:10.244+0800: 179227.560: [weak refs processing, 93.3276296 secs] ... [1 CMS-remark: 415575980K(566231040K)] 416281199K(618659840K), 94.1390159 secs] [Times: user=107.70 sys=10.29, real=94.14 secs]
可以看到，remark階段耗時94.14s，其中weak refs processing階段耗時93.33s。那問題肯定出在對弱引用的處理上。當然要是為了降低weak refs processing階段耗時，可以使用引數-XX:+ParallelRefProcEnabled開啟併發處理。
為什麼weak refs processing耗時這麼長？
雖然開啟併發處理引數可以簡單粗暴的降低GC耗時，但是為什麼Ranger外掛升級之後出現了這個問題還需要進一步深挖。
weak refs processing主要包括SoftReference、WeakReference、FinalReference、PhantomReference以及JNI Weak Reference這五種Reference物件的處理。到底處理哪種引用物件耗時，需要新增引數-XX:+PrintReferenceGC，來具體顯示各種Reference的個數和處理時間。線上下環境新增引數之後復現該問題，對應的GC日誌（相對極端的一條）如下所示：
2022-01-17T14:51:26.616+0800: 2061.131: [GC (Allocation Failure) 2022-01-17T14:51:26.617+0800: 2061.131: [ParNew 2022-01-17T14:51:27.115+0800: 2061.630: [SoftReference, 0 refs, 0.0000930 secs] 2022-01-17T14:51:27.115+0800: 2061.630: [WeakReference, 156 refs, 0.0000494 secs] 2022-01-17T14:51:27.115+0800: 2061.630: [FinalReference, 1348 refs, 10.2301307 secs] 2022-01-17T14:51:37.345+0800: 2071.860: [PhantomReference, 0 refs, 95 refs, 0.0000758 secs] 2022-01-17T14:51:37.346+0800: 2071.860: [JNI Weak Reference, 0.0000177 secs]: 52844281K->5134129K(53476800K), 10.7291830 secs] 90304049K->43584416K(172316096K), 10.7294849 secs] [Times: user=20.36 sys=0.17, real=10.73 secs]
可以看到，這次YGC花費了10.73s，其中處理FinalReference的時間為10.23s，可見YGC問題是出在FinalReference的處理上。關於FinalReference的詳細解讀，可以參考 《JVM原始碼分析之FinalReference完全解讀》
為什麼Ranger外掛升級之後會導致FinalReference處理耗時變長？
FinalReference物件一般是某類重寫了finalize方法，那具體是哪個類呢？通常的辦法是使用jmap將堆dump下來使用MAT進行離線分析。然而實際測試環境要復現這個場景需要開比較大的堆，導致MAT分析比較困難。那有沒有其他辦法呢？
既然我們知道大概率是因為某個類重寫了finalize方法導致的這個問題，那有沒有什麼方法從JVM中找到這個類呢？答案是肯定的，可以使用arthas的sm方法搜尋JVM中某個方法。方法和結果如下所示：
[[email protected]]$ sm org.apache.* finalize -n 10000 org.apache.hadoop.hdfs.protocol.RollingUpgradeInfo finalize(J)V org.apache.ranger.plugin.policyengine.PolicyEngine finalize()V org.apache.ranger.plugin.policyengine.RangerPolicyRepository finalize()V org.apache.ranger.plugin.contextenricher.RangerAbstractContextEnricher finalize()V org.apache.log4j.AppenderSkeleton finalize()V
文章總結
本文結合HDFS生產線上NameNode的兩次YGC異常現象，分別介紹瞭如何結合日誌進行GC問題的排查分析。這裡有兩個比較常見的現象總結：
- 如果user+sys的時間遠小於real的值，這種情況說明JVM暫停的時間沒有消耗在CPU執行上，而大概率卡頓在IO上。
- 如果新生代GC時間比較長，可以嘗試新增引數-XX:+PrintReferenceGC來確認各種Reference的個數和處理時間。確認是否是某種Reference的GC時間較長。