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

 

轉載請註明 AIQ - 最專業的機器學習大資料社群  http://www.6aiq.com

AIQ 機器學習大資料 知乎專欄 點選關注

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

背景

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

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

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

偵查思路

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

排查路線：

既然上面已經定位到是 FULL GC 問題，我們就可以用常用 FULL C 的手段去解決。在這次故障分析我們是利用 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 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 supplier)方法啟動預設的ForkJoinPool.commonPool()去執行

• 改為呼叫CompletableFuture supplyAsync(Supplier 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 實現。