記一次 Java 應用內存泄漏的定位過程
問題現象
最近，筆者負責測試的某個算法模塊機器出現大量報警，報警表現為機器CPU持續高占用。該算法模塊是一個優化算法，本身就是CPU密集型應用，一開始懷疑可能是算法在正常運算，但很快這種猜測就被推翻：同算法同學確認后，該算法應用只使用了一個核心，而報警時，一個算法進程占用了服務機器的全部8個核心，這顯然不是正常計算造成的。
定位步驟
首先按照CPU問題的定位思路進行定位，對 Java 調用堆棧進行分析：
1. 使用top -c 查看 CPU 占用高的進程：
，從 top 命令的結果看，19272 號進程 CPU 占用率最高，基本確定問題是該進程引起，可以從 Command 欄看到這正是算法模塊程序，注意圖是線下4C機器上復現時的截圖。
2. 使用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。
3. 使用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。
1. 增加啟動參數，展示詳細 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 的內存泄漏問題比較難以定位，下面針對一些常見的內存泄漏場景做介紹：
1. 持續在堆上創建對象而不釋放。例如，持續不斷的往一個列表中添加對象，而不對列表清空。這種問題，通?？梢越o程序運行時添加 JVM 參數-Xmx 指定一個較小的運行堆大小，這樣可以比較容易的發現這類問題。
2. 不正 所有的靜態變量。
3. 對大 String 對象調用 String.intern()方法，該方法會從字符串常量池中查詢當前字符串是否存在，若不存在就會將當前字符串放入常量池中。而在 jdk6 之前，字符串常量存儲在 PermGen 區的，但是默認情況下 PermGen 區比較小，所以較大的字符串調用此方法，很容易會觸發內存溢出問題。
4. 打開的輸入流、連接沒有爭取關閉。由于這些資源需要對應的內存維護狀態，因此不關閉會導致這些內存無法釋放。
如何進行定位
以上介紹了一些常見的內存泄漏場景，在實際的問題中還需要針對具體的代碼進行確定排查。下面結合之前的頻繁 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依賴即可修復該問題。
