[[418418]]

問題現象

最近，筆者負責測試的某個算法模塊機器出現大量報警，報警表現為機器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.  持續在堆上創建對象而不釋放。例如，持續不斷的往一個列表中添加對象，而不對列表清空。這種問題，通常可以給程序運行時添加 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依賴即可修復該問題。