[[418418]]

問題現(xiàn)象

最近，筆者負(fù)責(zé)測試的某個算法模塊機器出現(xiàn)大量報警，報警表現(xiàn)為機器CPU持續(xù)高占用。該算法模塊是一個優(yōu)化算法，本身就是CPU密集型應(yīng)用，一開始懷疑可能是算法在正常運算，但很快這種猜測就被推翻：同算法同學(xué)確認(rèn)后，該算法應(yīng)用只使用了一個核心，而報警時，一個算法進(jìn)程占用了服務(wù)機器的全部8個核心，這顯然不是正常計算造成的。

定位步驟

首先按照CPU問題的定位思路進(jìn)行定位，對 Java 調(diào)用堆棧進(jìn)行分析：

    1.  使用top -c 查看 CPU 占用高的進(jìn)程：   

，從 top 命令的結(jié)果看，19272 號進(jìn)程 CPU 占用率最高，基本確定問題是該進(jìn)程引起，可以從 Command 欄看到這正是算法模塊程序，注意圖是線下4C機器上復(fù)現(xiàn)時的截圖。

    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 

從結(jié)果可以看到，出現(xiàn)問題的線程主要是 19273-19277。

    3.  使用jstack查看出現(xiàn)問題的線程堆棧信息。

由于 jstack 使用的線程號是十六進(jìn)制，因此需要先把線程號從十進(jìn)制轉(zhuǎn)換為十六進(jìn)制。 

$ 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 導(dǎo)致的 CPU 被占滿。

我們可以使用 jstat 命令查看 GC 統(tǒng)計： 

$ 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 

重點關(guān)注一下幾列：

YGC：年輕代垃圾回收次數(shù)

YGCT：年輕代垃圾回收消耗時間

FGC：老年代垃圾回收次數(shù)

FGCT：老年代垃圾回收消耗時間

GCT：垃圾回收消耗總時間

可以看到，20s 的時間中進(jìn)行了 5 次 full GC，僅僅耗費在 GC 的時間已經(jīng)到了 17s。

    1.  增加啟動參數(shù)，展示詳細(xì) GC 過程。通過增加 jvm 參數(shù)，更快暴露 GC 問題，并展示 GC 詳細(xì)過程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 高負(fù)載的根本原因是內(nèi)存不足導(dǎo)致頻繁 GC。

根本原因

雖然我們經(jīng)過上面的分析可以知道，是頻繁 GC 導(dǎo)致的 CPU 占滿，但是并沒有找到問題的根本原因，因此也無從談起如何解決。GC 的直接原因是內(nèi)存不足，懷疑算法程序存在內(nèi)存泄漏。

為什么會內(nèi)存泄漏

雖然 Java 語言天生就有垃圾回收機制，但是這并不意味著 Java 就沒有內(nèi)存泄漏問題。

正常情況下，在 Java 語言中如果一個對象不再被使用，那么 Java 的垃圾回收機制會及時把這些對象所占用的內(nèi)存清理掉。但是有些情況下，有些對象雖然不再被程序使用，但是仍然有引用指向這些對象，所以垃圾回收機制無法處理。隨著這些對象占用內(nèi)存數(shù)量的增長，最終會導(dǎo)致內(nèi)存溢出。

Java 的內(nèi)存泄漏問題比較難以定位，下面針對一些常見的內(nèi)存泄漏場景做介紹：

    1.  持續(xù)在堆上創(chuàng)建對象而不釋放。例如，持續(xù)不斷的往一個列表中添加對象，而不對列表清空。這種問題，通?？梢越o程序運行時添加 JVM 參數(shù)-Xmx 指定一個較小的運行堆大小，這樣可以比較容易的發(fā)現(xiàn)這類問題。

    2. 不正 所有的靜態(tài)變量。

    3.  對大 String 對象調(diào)用 String.intern()方法，該方法會從字符串常量池中查詢當(dāng)前字符串是否存在，若不存在就會將當(dāng)前字符串放入常量池中。而在 jdk6 之前，字符串常量存儲在 PermGen 區(qū)的，但是默認(rèn)情況下 PermGen 區(qū)比較小，所以較大的字符串調(diào)用此方法，很容易會觸發(fā)內(nèi)存溢出問題。

    4.  打開的輸入流、連接沒有爭取關(guān)閉。由于這些資源需要對應(yīng)的內(nèi)存維護(hù)狀態(tài)，因此不關(guān)閉會導(dǎo)致這些內(nèi)存無法釋放。

如何進(jìn)行定位

以上介紹了一些常見的內(nèi)存泄漏場景，在實際的問題中還需要針對具體的代碼進(jìn)行確定排查。下面結(jié)合之前的頻繁 GC 問題，講解一下定位的思路，以及相關(guān)工具的使用方法。

線上定位

對于線上服務(wù)，如果不能開啟 Debug 模式，那么可用的工具較少。推薦方式：

使用 top -c 命令查詢 Java 高內(nèi)存占用程序的進(jìn)程 pid。然后使用 jcmd 命令獲取進(jìn)程中對象的計數(shù)、內(nèi)存占用信息。 

$ 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 

結(jié)果中，#instances 為對象數(shù)量，#bytes 為占用內(nèi)存大小，單位是 byte，class name 為對應(yīng)的類名。

排名第一的是 Java 原生類型，實際上是 long 類型。

另外，要注意的是結(jié)果中的類可能存在包含關(guān)系，例如一個類中含有多個 long 類型數(shù)據(jù)，那 long 對應(yīng)的計數(shù)也會增加，所以我們要排除一些基本類型，它們可能是我們程序中使用導(dǎo)致的計數(shù)增加，重點關(guān)注我們程序中的類。

如果僅僅有 jcmd 的結(jié)果，其實很難直接找到問題的根本原因。如果問題不能在線下復(fù)現(xiàn)，我們基本上只能針對計數(shù)較多的類名跟蹤變量的數(shù)據(jù)流，重點關(guān)注 new 對象附近的代碼邏輯。觀察代碼邏輯時，重點考慮上述幾種常見內(nèi)存泄漏場景。

線下定位

如果內(nèi)存泄漏問題可以在線下復(fù)現(xiàn)，那么問題定位的工具就比較豐富了。下面主要推薦的兩種工具，VisualVM & IDEA。

這里主要講一下IDEA調(diào)試定位思路：

使用 IDEA 調(diào)試器定位內(nèi)存泄漏問題

如果以上過程依然不能有效的分析出問題的根本原因，還可以使用 IDEA 的調(diào)試功能進(jìn)行定位。

配置好程序的運行參數(shù)，正常復(fù)現(xiàn)問題之后，對程序打斷點并逐步追蹤。

重點關(guān)注的是程序需要大量運行時間的代碼部分，我們可以使用調(diào)試暫停功能獲得一個內(nèi)存快照。

然后在此運行并暫停，這時候在調(diào)試的 Memory 視圖中可以看到哪些類在快速增加?；旧峡梢詳喽▎栴}的原因是兩次運行中 new 該對象的語句。

定位結(jié)果

經(jīng)過上述定位步驟，最終發(fā)現(xiàn)問題的根本原因，在求解器的 LocalSearch 階段，如果使用了禁忌搜索（Tabu Search）策略，并且長時間找不到更好的解，會不斷把當(dāng)前經(jīng)歷過的解加到禁忌表中。對應(yīng)的代碼部分，finalListScore 是一個 list，在 55 行代碼不斷的添加 moveScope 對象，導(dǎo)致了內(nèi)存泄漏：

解決方案

在求解器該處代碼對 finalListScore 進(jìn)行長度限制，添加對象前發(fā)現(xiàn)達(dá)到了上限就清空，徹底避免內(nèi)存泄漏的發(fā)生。由于出問題的是一個開源求解器框架：optaplanner，為了方便以后維護(hù)，按照開源項目貢獻(xiàn)流程，把改fix提PR給項目即可，如何給開源項目提PR可以參考社區(qū)文章：https://testerhome.com/topics/2114。

細(xì)節(jié)參考PR鏈接：https://github.com/kiegroup/optaplanner/pull/726。

項目維護(hù)者從代碼維護(hù)的角度沒有接受這個PR，但是使用了類似的fix思路最終修復(fù)了這個存在了幾年bug：https://github.com/kiegroup/optaplanner/pull/763。

最后，算法模塊升級到最新版本的optaplanner依賴即可修復(fù)該問題。