記一次 Java 應用記憶體洩漏的定位過程

rihkddd發表於2020-06-03

問題現象

最近，筆者負責測試的某個演算法模組機器出現大量報警，報警表現為機器 CPU 持續高佔用。該演算法模組是一個最佳化演算法，本身就是 CPU 密集型應用，一開始懷疑可能是演算法在正常運算，但很快這種猜測就被推翻：同演算法同學確認後，該演算法應用只使用了一個核心，而報警時，一個演算法程序佔用了服務機器的全部 8 個核心，這顯然不是正常計算造成的。

定位步驟

首先按照 CPU 問題的定位思路進行定位，對 Java 呼叫堆疊進行分析：

使用top -c 檢視 CPU 佔用高的程序：
，從 top 命令的結果看，19272 號程序 CPU 佔用率最高，基本確定問題是該程序引起，可以從 Command 欄看到這正是演算法模組程式，注意圖是線下 4C 機器上覆現時的截圖。

使用ps -mp pid -o THREAD,tid,time命令定位問題執行緒。

ps -mp 19272 -o THREAD,tid,time
USER     %CPU PRI SCNT WCHAN  USER SYSTEM   TID     TIME
USER    191   -    - -         -      -     - 00:36:54
USER    0.0  19    - futex_    -      - 19272 00:00:00
USER   68.8  19    - futex_    -      - 19273 00:13:18
USER   30.2  19    - -         -      - 19274 00:05:50
USER   30.2  19    - -         -      - 19275 00:05:50
USER   30.2  19    - -         -      - 19276 00:05:50
USER   30.1  19    - -         -      - 19277 00:05:49
USER    0.4  19    - futex_    -      - 19278 00:00:05
USER    0.0  19    - futex_    -      - 19279 00:00:00
USER    0.0  19    - futex_    -      - 19280 00:00:00
USER    0.0  19    - futex_    -      - 19281 00:00:00
USER    0.4  19    - futex_    -      - 19282 00:00:04
USER    0.3  19    - futex_    -      - 19283 00:00:03
USER    0.0  19    - futex_    -      - 19284 00:00:00
USER    0.0  19    - futex_    -      - 19285 00:00:00
USER    0.0  19    - futex_    -      - 19286 00:00:00
USER    0.0  19    - skb_wa    -      - 19362 00:00:00

從結果可以看到，出現問題的執行緒主要是 19273-19277。

使用jstack檢視出現問題的執行緒堆疊資訊。

由於 jstack 使用的執行緒號是十六進位制，因此需要先把執行緒號從十進位制轉換為十六進位制。

$ printf "%x\n" 19273
4b49
$ jstack 12262 |grep -A 15 4b49
"main" #1 prio=5 os_prio=0 tid=0x00007f98c404c000 nid=0x4b49 runnable [0x00007f98cbc58000]
java.lang.Thread.State: RUNNABLE
    at java.util.ArrayList.iterator(ArrayList.java:840)
    at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.updateSolution(MultiSkuDcAssignmentEasyScoreCalculator.java:794)
    at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.calculateScore(MultiSkuDcAssignmentEasyScoreCalculator.java:80)
    at optional.score.MultiSkuDcAssignmentEasyScoreCalculator.calculateScore(MultiSkuDcAssignmentEasyScoreCalculator.java:17)
    at org.optaplanner.core.impl.score.director.easy.EasyScoreDirector.calculateScore(EasyScoreDirector.java:60)
    at org.optaplanner.core.impl.score.director.AbstractScoreDirector.doAndProcessMove(AbstractScoreDirector.java:188)
    at org.optaplanner.core.impl.localsearch.decider.LocalSearchDecider.doMove(LocalSearchDecider.java:132)
    at org.optaplanner.core.impl.localsearch.decider.LocalSearchDecider.decideNextStep(LocalSearchDecider.java:116)
    at org.optaplanner.core.impl.localsearch.DefaultLocalSearchPhase.solve(DefaultLocalSearchPhase.java:70)
    at org.optaplanner.core.impl.solver.AbstractSolver.runPhases(AbstractSolver.java:88)
    at org.optaplanner.core.impl.solver.DefaultSolver.solve(DefaultSolver.java:191)
    at app.DistributionCenterAssignmentApp.main(DistributionCenterAssignmentApp.java:61)

"VM Thread" os_prio=0 tid=0x00007f98c419d000 nid=0x4b4e runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f98c405e800 nid=0x4b4a runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f98c4060800 nid=0x4b4b runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f98c4062800 nid=0x4b4c runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f98c4064000 nid=0x4b4d runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f98c4240800 nid=0x4b56 waiting on condition

可以看到，除了 0x4b49 執行緒是正常工作執行緒，其它都是 gc 執行緒。

此時懷疑：是頻繁 GC 導致的 CPU 被佔滿。

我們可以使用 jstat 命令檢視 GC 統計：

$ jstat -gcutil 19272 2000 10
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
0.00   0.00  22.71 100.00  97.16  91.53   2122   19.406   282  809.282  828.688
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   283  809.282  828.688
0.00   0.00  92.46 100.00  97.16  91.53   2122   19.406   283  812.730  832.135
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   284  812.730  832.135
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   285  815.965  835.371
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   285  815.965  835.371
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   286  819.492  838.898
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   286  819.492  838.898
0.00   0.00 100.00 100.00  97.16  91.53   2122   19.406   287  822.751  842.157
0.00   0.00  30.78 100.00  97.16  91.53   2122   19.406   287  825.835  845.240

重點關注一下幾列：
YGC：年輕代垃圾回收次數
YGCT：年輕代垃圾回收消耗時間
FGC：老年代垃圾回收次數
FGCT：老年代垃圾回收消耗時間
GCT：垃圾回收消耗總時間
可以看到，20s 的時間中進行了 5 次 full GC，僅僅耗費在 GC 的時間已經到了 17s。

增加啟動引數，展示詳細 GC 過程。透過增加 jvm 引數，更快暴露 GC 問題，並展示 GC 詳細過程java -Xmx1024m -verbose:gc。

[Full GC (Ergonomics)  1046527K->705881K(1047552K), 1.8974837 secs]
[Full GC (Ergonomics)  1046527K->706191K(1047552K), 2.5837756 secs]
[Full GC (Ergonomics)  1046527K->706506K(1047552K), 2.6142270 secs]
[Full GC (Ergonomics)  1046527K->706821K(1047552K), 1.9044987 secs]
[Full GC (Ergonomics)  1046527K->707130K(1047552K), 2.0856625 secs]
[Full GC (Ergonomics)  1046527K->707440K(1047552K), 2.6273944 secs]
[Full GC (Ergonomics)  1046527K->707755K(1047552K), 2.5668877 secs]
[Full GC (Ergonomics)  1046527K->708068K(1047552K), 2.6924427 secs]
[Full GC (Ergonomics)  1046527K->708384K(1047552K), 3.1084132 secs]
[Full GC (Ergonomics)  1046527K->708693K(1047552K), 1.9424100 secs]
[Full GC (Ergonomics)  1046527K->709007K(1047552K), 1.9996261 secs]
[Full GC (Ergonomics)  1046527K->709314K(1047552K), 2.4190958 secs]
[Full GC (Ergonomics)  1046527K->709628K(1047552K), 2.8139132 secs]
[Full GC (Ergonomics)  1046527K->709945K(1047552K), 3.0484079 secs]
[Full GC (Ergonomics)  1046527K->710258K(1047552K), 2.6983539 secs]
[Full GC (Ergonomics)  1046527K->710571K(1047552K), 2.1663274 secs]

至此基本可以確定，CPU 高負載的根本原因是記憶體不足導致頻繁 GC。

根本原因

雖然我們經過上面的分析可以知道，是頻繁 GC 導致的 CPU 佔滿，但是並沒有找到問題的根本原因，因此也無從談起如何解決。GC 的直接原因是記憶體不足，懷疑演算法程式存在記憶體洩漏。

為什麼會記憶體洩漏

雖然 Java 語言天生就有垃圾回收機制，但是這並不意味著 Java 就沒有記憶體洩漏問題。

正常情況下，在 Java 語言中如果一個物件不再被使用，那麼 Java 的垃圾回收機制會及時把這些物件所佔用的記憶體清理掉。但是有些情況下，有些物件雖然不再被程式使用，但是仍然有引用指向這些物件，所以垃圾回收機制無法處理。隨著這些物件佔用記憶體數量的增長，最終會導致記憶體溢位。

Java 的記憶體洩漏問題比較難以定位，下面針對一些常見的記憶體洩漏場景做介紹：

持續在堆上建立物件而不釋放。例如，持續不斷的往一個列表中新增物件，而不對列表清空。這種問題，通常可以給程式執行時新增 JVM 引數-Xmx 指定一個較小的執行堆大小，這樣可以比較容易的發現這類問題。
不正確的使用靜態物件。因為 static 關鍵字修飾的物件的生命週期與 Java 程式的執行週期是一致的，所以垃圾回收機制無法回收靜態變數引用的物件。所以，發生記憶體洩漏問題時，我們要著重分析所有的靜態變數。
對大 String 物件呼叫 String.intern() 方法，該方法會從字串常量池中查詢當前字串是否存在，若不存在就會將當前字串放入常量池中。而在 jdk6 之前，字串常量儲存在 PermGen 區的，但是預設情況下 PermGen 區比較小，所以較大的字串呼叫此方法，很容易會觸發記憶體溢位問題。
開啟的輸入流、連線沒有爭取關閉。由於這些資源需要對應的記憶體維護狀態，因此不關閉會導致這些記憶體無法釋放。

如何進行定位

以上介紹了一些常見的記憶體洩漏場景，在實際的問題中還需要針對具體的程式碼進行確定排查。下面結合之前的頻繁 GC 問題，講解一下定位的思路，以及相關工具的使用方法。

線上定位

對於線上服務，如果不能開啟 Debug 模式，那麼可用的工具較少。推薦方式：
使用 top -c 命令查詢 Java 高記憶體佔用程式的程序 pid。然後使用 jcmd 命令獲取程序中物件的計數、記憶體佔用資訊。

$ jcmd 24600 GC.class_histogram |head -n 10
24600:

 num     #instances         #bytes  class name
----------------------------------------------
   1:       2865351      103154208  [J
   2:       1432655       45844960  org.optaplanner.core.impl.localsearch.scope.LocalSearchMoveScope
   3:       1432658       34383792  org.optaplanner.core.api.score.buildin.bendablelong.BendableLongScore
   4:       1193860       28652640  org.optaplanner.core.impl.heuristic.selector.move.generic.ChangeMove
   5:        241961       11986056  [Ljava.lang.Object;
   6:        239984        5759616  java.util.ArrayList

結果中，#instances 為物件數量，#bytes 為佔用記憶體大小，單位是 byte，class name 為對應的類名。
排名第一的是 Java 原生型別，實際上是 long 型別。

另外，要注意的是結果中的類可能存在包含關係，例如一個類中含有多個 long 型別資料，那 long 對應的計數也會增加，所以我們要排除一些基本型別，它們可能是我們程式中使用導致的計數增加，重點關注我們程式中的類。

如果僅僅有 jcmd 的結果，其實很難直接找到問題的根本原因。如果問題不能線上下復現，我們基本上只能針對計數較多的類名跟蹤變數的資料流，重點關注 new 物件附近的程式碼邏輯。觀察程式碼邏輯時，重點考慮上述幾種常見記憶體洩漏場景。

線下定位

如果記憶體洩漏問題可以線上下復現，那麼問題定位的工具就比較豐富了。下面主要推薦的兩種工具，VisualVM & IDEA。

這裡主要講一下 IDEA 除錯定位思路：

使用 IDEA 偵錯程式定位記憶體洩漏問題

如果以上過程依然不能有效的分析出問題的根本原因，還可以使用 IDEA 的除錯功能進行定位。
配置好程式的執行引數，正常復現問題之後，對程式打斷點並逐步追蹤。

重點關注的是程式需要大量執行時間的程式碼部分，我們可以使用除錯暫停功能獲得一個記憶體快照。
然後在此執行並暫停，這時候在除錯的 Memory 檢視中可以看到哪些類在快速增加。基本上可以斷定問題的原因是兩次執行中 new 該物件的語句。

定位結果

經過上述定位步驟，最終發現問題的根本原因，在求解器的 LocalSearch 階段，如果使用了禁忌搜尋（Tabu Search）策略，並且長時間找不到更好的解，會不斷把當前經歷過的解加到禁忌表中。對應的程式碼部分，finalListScore 是一個 list，在 55 行程式碼不斷的新增 moveScope 物件，導致了記憶體洩漏：

解決方案

在求解器該處程式碼對 finalListScore 進行長度限制，新增物件前發現達到了上限就清空，徹底避免記憶體洩漏的發生。由於出問題的是一個開源求解器框架：optaplanner，為了方便以後維護，按照開源專案貢獻流程，把改 fix 提 PR 給專案即可，如何給開源專案提 PR 可以參考社群文章：https://testerhome.com/topics/2114。

細節參考 PR 連結：https://github.com/kiegroup/optaplanner/pull/726。
專案維護者從程式碼維護的角度沒有接受這個 PR，但是使用了類似的 fix 思路最終修復了這個存在了幾年 bug：https://github.com/kiegroup/optaplanner/pull/763。

最後，演算法模組升級到最新版本的 optaplanner 依賴即可修復該問題。

一次排查Java專案記憶體洩漏的過程
2018-08-17
Java記憶體
記一次使用windbg排查記憶體洩漏的過程
2020-05-31
記憶體
Java應用程式中的記憶體洩漏及記憶體管理
2019-08-29
Java記憶體
一次 Java 記憶體洩漏的排查
2020-03-15
Java記憶體
PHP 記憶體洩漏分析定位
2018-03-13
PHP記憶體
記一次透過Memory Analyzer分析記憶體洩漏的解決過程
2020-06-22
記憶體
Java記憶體洩漏
2020-12-06
Java記憶體
記憶體洩漏-原因、避免和定位
2022-01-13
記憶體
記一次"記憶體洩露"排查過程
2019-10-15
記憶體洩露
記憶體洩漏定位工具之 valgrind 使用
2022-07-01
記憶體
記錄一次記憶體洩漏排查過程
2023-11-06
記憶體
記一次堆外記憶體洩漏分析
2024-06-03
記憶體
記一次尷尬的Java應用記憶體洩露排查
2018-09-22
Java記憶體洩露
記一則伺服器記憶體洩漏解決過程
2020-11-18
伺服器記憶體
定位並修復 Go 中的記憶體洩漏
2021-11-01
Go記憶體
java記憶體溢位和記憶體洩漏的區別
2018-04-27
Java記憶體溢位
記一次堆外記憶體洩漏排查過程
2024-06-10
記憶體
一次 Java 記憶體洩漏排查過程，漲姿勢
2021-09-09
Java記憶體
[Java基礎]記憶體洩漏和記憶體溢位
2024-08-07
Java記憶體溢位
Java棧溢位|記憶體洩漏|記憶體溢位
2024-08-13
Java記憶體溢位
Java記憶體洩漏解決之道
2018-11-05
Java記憶體
記憶體洩漏的原因
2018-07-10
記憶體
記一次使用 laravel-s 記憶體洩漏
2022-01-08
Laravel記憶體
jvm 記憶體洩漏
2024-11-24
JVM記憶體
Android 記憶體洩漏
2020-11-19
Android記憶體
js記憶體洩漏
2019-02-16
JS記憶體
Android記憶體洩漏
2018-03-11
Android記憶體
MAT工具定位分析Java堆記憶體洩漏問題方法
2021-06-24
Java記憶體
分析記憶體洩漏和goroutine洩漏
2021-10-22
記憶體Go
手把手教你定位Flutter PlatformView記憶體洩漏
2020-03-13
FlutterPlatformView記憶體
記一次 Ruby 記憶體洩漏的排查和修復
2019-04-03
記憶體
翻譯 | 理解Java中的記憶體洩漏
2019-02-11
Java記憶體
納尼，Java 存在記憶體洩洩洩洩洩洩漏嗎？
2019-05-22
Java記憶體
記憶體的分配與釋放，記憶體洩漏
2019-05-12
記憶體
WebView引起的記憶體洩漏
2019-09-25
WebView記憶體
記憶體洩漏的定位與排查：Heap Profiling 原理解析
2021-11-23
記憶體
【記憶體洩漏和記憶體溢位】JavaScript之深入淺出理解記憶體洩漏和記憶體溢位
2024-11-06
記憶體溢位JavaScript
valgrind 記憶體洩漏分析
2021-05-17
記憶體