一次生產系統Full GC問題分析與排查總結

背景

最近某線上業務系統生產環境頻頻CPU使用率過低，頻繁告警，通過重啟可以緩解，但是過了一段時間又會繼續預警，線上兩個服務節點相繼出現CPU資源緊張，導致伺服器卡死不可用，通過告警資訊可以看到以下問題：

從上圖可以看到，目前zabbix監控展示CPU空閒時間已經低於預警線，證明目前CPU資源佔用過高，考慮到最近並沒有特別開發任務上線，但是最近有釋出過一個新的營銷活動，有可能是因為突然使用者量增長進一步凸顯該問題。

從Pinpoint APM監控工具看到，從9月3號下午開始，系統開始出現頻繁full gc的情況，而剛好9月3號下午釋出了一個新活動，基本可以斷定這可能是使用者量突然激增，凸顯潛伏已久的系統問題，於是接下來方向就可以往full gc方向去排查，找出引起full gc的程式碼。

偵查思路

往FULL GC方向偵查，懷疑存在記憶體洩露

排查路線：

既然上面已經定位到是FULL GC問題，我們就可以用常用FULL GC的手段去解決。在這次故障分析我們是利用MAT去做分析，主要對以下幾點做排查：

• 程式是否記憶體洩露
• 程式中是否存在不合理的大物件佔用
• 程式中部分物件產生記憶體是否可以優化

匯出JVM dump檔案和jstack執行緒日誌,保留案發現場

因為公司不允許個人訪問線上伺服器，於是讓運維同學在伺服器出現故障時匯出jvm dump檔案和jstack執行緒日誌，如果自己有許可權去生產伺服器的話，可以通過以下指令匯出jvm dump檔案

jmap -dump:format=b,file=檔名 [服務程序ID]

結合MAT分析工具，找出可疑物件

使用MAT前，先簡單介紹下MAT的一些常用的指標和功能概念：

• Shallow Heap指標：物件本身佔用記憶體的大小，不包含對其他物件的引用，也就是物件頭加成員變數（不是成員變數的值）的總和

• Retained Heap指標：是該物件自己的shallow size，加上從該物件能直接或間接訪問到物件的shallow size之和。換句話說，retained size是該物件被GC之後所能回收到記憶體的總和。

• Histogram動作：列出每個類的例項數
• Dominator Tree動作
  ：列出最大的物件以及它們儲存的內容
• Top Consumers動作: 按照類和包分組列印花費最高的例項
• Duplicate Classes動作: 檢測由多個類載入器載入的類
• Leak Suspects報告: 包括洩密嫌疑人和系統概述
• Top Components報告：列出大於總堆的1％的元件的報告

通過Leak Suspects排查記憶體洩露

在Ecplise Memory Analyzer匯入JVM dump檔案，點選工具欄上的 Leak Suspects 選單項來生成記憶體洩露分析報告，也可以直接點選餅圖下方的 Reports->Leak Suspects連結來生成報告。如圖：

MAT工具分析了heap dump後在介面上非常直觀的展示了一個餅圖，該圖深色區域被懷疑有記憶體洩漏，可以發現整個heap才1.5G記憶體，深色區域就佔了57.76%。接下來是一個簡短的描述，MAT告訴我們存在兩個可疑問題
- Problem Suspect 1：告訴我們java.lang.Thread執行緒例項佔用了大量記憶體，一共存在5154個例項，並且明確指出system class loader載入的java.lang.Thread例項佔據了643,021,136 (41.03%)位元組 ，並建議用關鍵字”java.lang.Thread”進行檢查。所以，MAT通過簡單的兩句話就說明了問題所在，就算使用者沒什麼處理記憶體問題的經驗。在下面還有一個”Details”連結，MAT給了一個參考類。如圖：

• Problem Suspect 2: 告訴我們jdk.nashorn.internal.runtime.Context執行緒例項佔用了大量記憶體,並且明確指出sun.misc.Launcher$ExtClassLoader @ 0x9000cf78載入的jdk.nashorn.internal.runtime.Context例項佔據了262,229,320 (16.73%)位元組，並建議用關鍵字sun.misc.Launcher$ExtClassLoader @ 0x9000cf78 jdk.nashorn.internal.runtime.Context進行檢查

通過Top Consumers定位大物件

點選Actions->Top Consumers ，檢視大物件有哪些



從上圖可以看出，java.lang.Thread、jdk.nashorn.*和javax.script.*這些類例項佔據了大部分記憶體

問題分析

從上面分析報告，可疑大膽推斷以下結論：

• 大量java.lang.Thread例項，明顯是執行緒使用不合理，懷疑有地方不斷建立執行緒，沒有使用執行緒池導致
• 大量jdk.nashorn.internal.*和javax.script.*相關例項，而jdk.nashorn.*這個包是Nashorn JavaScript引擎的包，主要是nashorn用於在JVM上以原生方式執行動態的JavaScript程式碼來擴充套件Java的功能，javax.script包用於javascript與java互動操作。於是可以基本斷定這是跟javascript指令碼相關操作有關，應該是有地方不斷建立javascript指令碼相關物件沒有被回收。

結合以上兩點，推測應用程式執行緒和指令碼操作部分出現問題，與該系統相關開發人員溝通，確實該系統是有大量javascript指令碼操作，是通過Javascript指令碼做一些特性開發，然後在在java呼叫執行。嘗試使用包名jdk.nashorn查詢運維匯出的jstack執行緒日誌，看看最接近的業務程式碼是什麼

果然看到了執行緒日誌裡面找到了疑似執行緒操作的業務程式碼，通過檢視原始碼，一步步檢視呼叫鏈，發現了有個地方會每次例項初始化都會建立一份指令碼引擎


這段程式碼大概作用是把每個任務的規則指令碼存放在指令碼引擎，然後存放在threadLocal裡，每個MissionEventHandler例項初始化都會建立一個threadLocal用於存放當前執行緒任務指令碼，以防多執行緒操作同一個MissionEventHandler例項會引起指令碼因併發被篡改問題。而經過沿著呼叫鏈檢視原始碼瞭解，這些MissionEventHandler例項只會業務人員點選任務下線的時候才會進行銷燬處理，那就是隻要任務不下線，這些任務會一直存活在記憶體中。

但是隻要MissionEventHandler例項數量控制好，應該是不會出現上述大量指令碼相關例項引發頻繁FULL GC問題，接下來我們的偵查方向就是檢視MissionEventHandler例項建立源頭，是否系統存在批量建立該例項的程式碼？繼續沿著呼叫鏈檢視原始碼，發現了一個非同步觀察者類，它是用來通知訊息事件的，以下是其中一個方法

這裡是使用了CompletableFuture的supplyAsync(Supplier<U> supplier)方法進行非同步處理，再進一步檢視supplyAsync的原始碼



從上面程式碼可以看到，supplyAsync有2個過載方法，當我們不指定執行緒池，它預設是呼叫第一個方法，當ForkJoinPool.getCommonPoolParallelism() > 1才會使用commonPool執行緒池，否則該方法預設會每次建立一條新的執行緒去處理。那有沒有可能是ForkJoinPool.getCommonPoolParallelism()<=1 導致每次都建立新的執行緒呢?我們進一步檢視ForkJoinPool.getCommonPoolParallelism()原始碼，發現這方法使用Java 8中的ForkJoinPool.commonPool()可以使用一個特殊的ForkJoinPool。該池使用一個取決於可用核心數量的預設並行度。一般情況下，預設的並行度是CPU核心數-1，該系統在生產環境執行的伺服器核數為2，那就是並行度為1，即這裡的ForkJoinPool.getCommonPoolParallelism()=1,意味著CompletableFuture的supplyAsync方法在這裡處理業務是每次都建立一條新的執行緒去處理。

總結

根據上面的分析，一切都真相大白，之前看到的大量java.lang.Thread例項就是因為處理業務時，預設每次都會開啟一條新的執行緒，導致出現大量的執行緒例項，而這些大量的執行緒例項又會引發大量的通知訊息操作，導致持有的指令碼相關例項沒法被回收，從而引發了大量jdk.nashorn.internal.*和javax.script.* 的例項佔據堆記憶體。

解決方案

這裡的解決方案很簡單，這裡引發的問題都是因為沒有使用到執行緒池導致的，可以採取以下兩種措施:

• 通過在tomcat配置jvm啟動引數-Djava.util.concurrent.ForkJoinPool.common.parallelism=2,可以讓supplyAsync(Supplier<U> supplier)方法啟動預設的ForkJoinPool.commonPool()去執行
• 改為呼叫CompletableFuture<U> supplyAsync(Supplier<U> supplier,Executor executor)，給方法指定執行緒池(推薦)

在本次改造是使用第二個方案，建立了一個自定義執行緒池，然後指定執行緒池去執行操作，程式碼如下

上線後觀察監控

上線後通過PINPOINT觀察，再也沒出現FULL GC問題

Java引用法則說明

從最強到最弱，不同的引用（可到達性）級別反映了物件的生命週期。

• Strong Ref(強引用)：通常我們編寫的程式碼都是Strong Ref，於此對應的是強可達性，只有去掉強可達，物件才被回收。

• Soft Ref(軟引用)：對應軟可達性，只要有足夠的記憶體，就一直保持物件，直到發現記憶體吃緊且沒有Strong Ref時才回收物件。一般可用來實現快取，通過java.lang.ref.SoftReference類實現。

• Weak Ref(弱引用)：比Soft Ref更弱，當發現不存在Strong Ref時，立刻回收物件而不必等到記憶體吃緊的時候。通過java.lang.ref.WeakReference和java.util.WeakHashMap類實現。

• Phantom Ref(虛引用)：根本不會在記憶體中保持任何物件，你只能使用Phantom Ref本身。一般用於在進入finalize()方法後進行特殊的清理過程，通過 java.lang.ref.PhantomReference實現。