[三步法] 可視化分析定位線上 JVM 問題

2020 年 4 月 2 日
筆記

1. 取 GC 日誌文件

gc.log 文件大概張什麼樣呢，如下圖所示：

前提是線上 JVM 配置了以下參數：

題外話：JDK 版本 1.6，現在大部分互聯網企業應用系統應該是 1.8 以上了吧

# 在控制台輸出GC情況  -verbose:gc  # GC日誌輸出  -XX:+PrintGC  # GC日誌詳細輸出  -XX:+PrintGCDetails  # GC輸出時間戳  -XX:+PrintGCDateStamps  # GC日誌輸出指定文件中  -Xloggc:/log/gc.log

2. GC 日誌可視化

首先獲取到線上 GC 的日誌文件後，通過在線日誌分析工具（GCeasy）上傳文件分析，網址：https://gceasy.io/

如果出現以下頁面，說明 GC 日誌在線分析已經完成，可視化效果如下所示：

從上圖可以發現，「3 problems detected」，即識別出 3 個記憶體問題。

3. 在線 GC 可視化視圖解讀

1）JVM memory size（JVM 記憶體大小）

上圖左側是表格展示，右側是柱狀圖?展示，含義是一樣的。

按分代策略劃分	分配大小	已用大小
年輕代	149.75 M	149.75 M
老年代	5.84 G	5.84 G
永久代	427.52 M	256.5 M
年輕代 + 老年代 + 永久代	6.4 G	6.23 G

題外話：年輕代是不是分配的太小？

2） key Performance Indicators（關鍵指標展示）

從上圖可以看出：

Throughput：87.041%，即表示該系統吞吐量為 87.041%。一般 95% 以上算優。
Latency，即表示系統 GC 的停頓時間，平均暫停時間 70.3 ms，最大暫停時間約 13 s。

將上圖的 GC Pause 時間間隔調整為 100 ms，查看結果如下：

上圖顯示 100 ms 以內的 GC 次數 5105，佔總 GC 的 99.53%，說明 GC 的效果還可以。

題外話：99.53% GC 時間這麼短，為何系統宕機了，是死在了餘下的 0.47% 的 GC 上！！！

3）Interactive Graphs（GC 前後堆區大小變化視圖）

為了更好的了解 GC 垃圾回收對應的區域，可以參考這篇文章【從 Java 程式碼如何運行聊到 JVM 和對象的創建-分配-定位-布局-垃圾回收】回顧一下有關 JVM 記憶體布局的劃分情況。

題外話：對照圖例看折線圖變化

從上面的折線圖可以看出，曲線存在尖銳的變化，可能是問題的所在之處（存在記憶體泄漏或是記憶體溢出）。

Heap after GC：GC 之後的堆區空間佔用大小（堆區包括 Young GC 和 Full GC）

因為 Young Gen 區域的大小只有 149.75 M，所以 Young GC 後還是有對象不停的晉陞到 Old Gen，直到老年代分配不了了才發生第一次 CMS GC。

題外話：細心的你會發現在 10 點 25 分左右就已經發生了一次 Full GC，此時的堆空間僅僅佔用了 500M 左右，應該不會發生 Full GC 才對，那麼為什麼呢？這是由於如果一開始永久代大小沒有設置、或者初始值設置的很小，很有可能一開始就執行 CMS。

Heap before GC：GC 之前的堆區空間佔用大小（堆區包括 Young GC 和 Full GC）

從 Full GC 之前和之後的圖形對比分析，可以看出 JVM 進行 Full GC 時，記憶體幾乎沒有被回收（此時年輕代的垃圾回收可以忽略），而對象始終佔用堆區大小 6G 左右，所以出現頻繁的 Full GC。

GC Duration：GC 期間

Pause GC Duration：GC 停頓時間

Young GC 耗時的點位於圖的最下方（藍色的方塊點），Full GC（紅色的三角點）耗時在 11 點之後越來越長，基本都超過了 10s，且特別頻繁發生，說明此時 GC 已經無力回天了。

Reclaimed Bytes：GC 回收記憶體大小

從上圖可以看出，Young GC 正常（藍色方塊點），每次能回收 120M ~ 140M 的記憶體，幾乎所有的年輕代垃圾都被回收了；而在 11點之後系統頻繁發生 Full GC（紅色的三角點），但是回收的垃圾幾乎為零？回收的垃圾幾乎為零？回收的垃圾幾乎為零？

Young Gen：年輕代 GC 變化

從上圖可以看出，Young GC 之前（紅線），年輕代記憶體佔用大概有 140M左右，Young GC 之後（紫線），年輕代記憶體佔用大小 20M 以內。年輕代垃圾回收正常。也可以分開顯示 Young GC 前後變化，如下圖所示：

Old Gen：老年代 GC 變化

如上圖所示，Old GC 前後的曲線分不清，通過如下操作，可以只顯示 Old GC 前的曲線變化或者 Old GC 後的曲線變化：

從上圖可以看出，Old GC（老年代垃圾回收）和 Heap 區的 GC 類似，老年代對象佔用大小一直在增加，直到10點55分出現拐點，可能存在記憶體泄漏或溢出，需要結合 Heap Dump 文件分析。

題外話：一般出現這種尖銳的拐點都是有問題的。

Perm Gen：永久代 GC 變化

永久代一直變化不大，動態分配，佔用記憶體空間小於 450 M。

A & P：對象分配與晉陞（從年輕代晉陞到老年代）

隱藏記憶體分配的曲線變化，只顯示 Young ——> Old 的變化曲線，如下圖所示：

4）CMS Collection Phases Statistics（CMS 垃圾收集器統計圖表）

從上圖最左側的柱狀圖，可以清晰看到 CMS GC 的各個階段（可參考這篇文章【記一次生產頻繁出現 Full GC 的 GC日誌圖文詳解】詳細了解 CMS 各個階段都幹了啥

）的平均耗時；Full GC 平均耗時長達 11s；上圖最右側的餅狀圖，展示了各階段 GC 的累積時間；上圖最下面的表格匯總了各個階段 GC 的次數、時間等相關資訊，其中 2 分 40 秒進行了 5081 次 Young GC，平均耗時 31.6 毫秒，3 分 18 秒進行了 18次 Full GC，平均耗時 11 秒。

5）CMS GC Time（CMS GC 時間）

CMS GC 暫停的時間最大約 13s（時間過長），並發 GC 時間最大 5s（影響不大）。

6）Object Stats（對象統計）

從圖中可以看出，這段 GC 期間共創建 661.35 G 大小的數據，從年輕代晉陞到老年代的共有 11.88 G，平均每秒創建 243.23 M（遠遠超過分配給年輕代的大小【Young Gen = 149.75M】），平均每秒晉陞到老年代的對象有 4.37 M。也就是說對於堆區年輕代分配的空間不太合理。

7）Memory Leak（記憶體泄漏）

無記憶體泄漏

8）Safe Point Duration（安全點期間）

日誌沒有記錄。 JVM 需要配置一下參數才會記錄 safe point 相關資訊：

-XX:+PrintGCApplicationStoppedTime  -XX:+PrintGCApplicationConcurrentTime  -XX:+PrintSafepointStatistics  -XX:PrintSafepointStatisticsCount=1

題外話：GC 的標記階段需要 stop the world（STW），讓所有 Java 執行緒掛起，這樣 JVM 才可以安全地來標記對象。safe point 可以用來實現讓所有 Java 執行緒掛起的需求。

9）GC Causes （GC 原因）

從上圖可以看到，在 CMS 收集器觸發時，出現了 promotion failed（1次）和 concurrent mode failure（14次）現象（可參考這篇文章【記一次生產頻繁出現 Full GC 的 GC日誌圖文詳解】）：

promotion failed：該現象是在進行觸發年輕代 ParNew GC 時，存活的對象在 Survivor 區放不下，對象只能進入老年代，而此時老年代也放不下導致的。
concurrent mode failure：該現象是在執行 CMS 收集器回收垃圾的過程中同時有存活的對象放入老年代，而此時老年代空間不足，或者在做 ParNew GC 的時候，年輕代 Survivor 區放不下，需要放入老年代，而老年代也放不下而導致的。

4. 從 GC 日誌可視化入手，再去 pinpoint 系統監控探究問題所在

1）通過 Pinpoint 監控系統查看頻繁發生 Full GC 的系統應用所在的伺服器 JVM 參數配置情況，結果如下圖所示：

從圖中可以了解關於堆區只設置了 3 個參數，幾乎其他設置項是默認設置，沒有任何優化。

2）Pinpoint 監控堆區的使用，非堆區的記憶體使用情況：

可以看出，系統從 11點左右開始頻繁發生 Major GC（Full GC）。說明這期間系統已經不能對外響應了。CPU 使用率波動不大。從下圖可以看出，系統在 11點左右停止響應了。

也可以通過 Pinpoint 監控獲取這段時間的系統請求量，下圖中點的密集程度反映各時間請求量的大小，沒有激增，分布很均勻，只是存在大量響應耗時較長的請求（慢請求），可能正是因為這些慢請求導致整個系統響應變慢，系統中的大量對象無法被回收。

題外話：如何知道哪些請求是慢請求呢？在 Pinpoint 中只需要框選上圖中最上方的藍色點即可，找到對應的請求，然後分析原因，解決耗時長的介面。比如資料庫長時間不返回結果集導致連接被一直佔用，請求第三方介面時未設置超時時間等待響應或是 IO操作未在 finally 中關閉流等，則這些不會自動被 GC 回收的，導致記憶體泄漏。本文在這不做過多的說明。有機會再詳細聊聊這塊 ~

5. 接著看 Dump 文件分析

通過 MAT 分析 dump 文件（可參考這篇文章【MAT的使用】），導入 dump 文件即可，等 MAT 解析完會出現如下圖所示的介面：

MAT 發現結果會展示一個疑似引起問題的大對象（占堆區的 96.52%），如下圖所示：

打開對應的 Domaintor Tree，如下圖所示：

按對象的大小排序，依次展開第一個最大的對象中所引用的對象，發現裡面有一個集合，該集合里存有 1836555 個對象，導致 OOM 記憶體溢出，如下圖所示：

查看程式碼，看看是否是 SQL 查詢條件缺失，導致返回了表中的所有數據。

題外話：建議後端服務做參數校驗或限制資料庫最大返回條數。

6. 對 JVM 參數的優化及說明

1）可增大年輕代或者 Survivor 區的存儲空間，減少 Young GC 的次數。

# 初始堆大小  -Xms6144M  # 最大堆大小  -Xmx6144M  # 初始永久代大小  -XX:PermSize=1024M  # 最大永久代大小  -XX:MaxPermSize=1024M  # 年輕代大小  -Xmn2048M  # Survivor 區佔比  -XX:SurvivorRatio=3

2）提前觸發 CMS GC 和多次 Full GC 後進行記憶體整理，以提升 CMS GC 垃圾回收的效率。

# CMS 垃圾回收記憶體碎片化嚴重  -XX:+UseCMSCompactAtFullCollection  # 每 5 次 Full GC 之後進行一次老年代空間記憶體整理  # 而不是每 5 次 CMS 並發 GC 就做一次壓縮  -XX:CMSFullGCsBeforeCompaction=5  # 只是用設定的老年代回收閾值(下面指定的75%),和下面的參數配合使用  # 如果不指定，JVM 僅在第一次使用設定值，後續則自動調整。  -XX:+UseCMSInitiatingOccupancyOnly  # 當老年代空間被占 75% 時，就進行 CMS GC  #（而默認佔用 92% 時觸發 CMS GC）  # 在進行 CMS GC 時應該留更多的空間，  # 防止年輕代晉陞老年代失敗，出現 concurrent mode failure  -XX:CMSInitiatingOccupancyFraction=75

7. 小結

通過三步法定位線上環境 JVM 問題，如頻繁 Full GC 、記憶體泄漏或發生 OOM 現象，即將 GC 日誌、Dump 文件及 APM 監控系統結合在一起觀察分析，尋找出問題產生的根本原因，然後才能對症下藥，真正解決系統存在的問題或是隱患，使系統性能更穩健，響應更快，從而使用戶體驗更佳。