又是一個程式員粗心的程式碼引起頻繁FullGC的案例

精品專欄

 

• 死磕 Java 併發

• 死磕 Sharding-jdbc

這是笨神JVMPocket群裡一位名為”雲何*住“的同學提出來的問題，問題現象是CPU飆高並且頻繁FullGC。

重現問題

這位同學的業務程式碼比較複雜，為了簡化業務場景，筆者將其程式碼壓縮成如下的程式碼片段：

1. public class FullGCDemo {
3.     private static ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor(50,
4.             new ThreadPoolExecutor.DiscardOldestPolicy());
6.     public static void main(String[] args) throws Exception {
7.         executor.setMaximumPoolSize(50);
9.         // 模擬xxl-job 100ms 呼叫一次, 原始碼沒有這麼頻繁
10.         for (int i=0; i<Integer.MAX_VALUE; i++){
11.             buildBar();
12.             Thread.sleep(100);
13.         }
14.     }
16.     private static void buildBar(){
17.         List<FutureContract> futureContractList = getAllFutureContract();
18.         futureContractList.forEach(contract -> {
19.             // do something
20.             executor.scheduleWithFixedDelay(() -> {
21.                 try{
22.                     doFutureContract(contract);
23.                 }catch (Exception e){
24.                     e.printStackTrace();
25.                 }
26.             }, 2, 3, TimeUnit.SECONDS);
27.         });
28.     }
30.     private static void doFutureContract(FutureContract contract){
31.         // do something with futureContract
32.     }
34.     private static List<FutureContract> getAllFutureContract(){
35.         List<FutureContract> futureContractList = new ArrayList<>();
36.         // 問題程式碼這裡每次只會new不到10個物件, 我這裡new了100個是為了更快重現問題
37.         for (int i = 0; i 100; i++) {
38.             FutureContract contract = new FutureContract(i, ... ...);
39.             futureContractList.add(contract);
40.         }
41.         return futureContractList;
42.     }
43. }

說明，為了更好的還原問題，FutureContract.java 的定義建議儘量與問題程式碼保持一致：

• 16個BigDecimal型別屬性
• 3個Long型別屬性
• 3個String型別屬性
• 4個Integer型別屬性
• 2個Date型別屬性

問題程式碼執行時的JVM引數如下（JDK8）：

1. java -Xmx256m -Xms256m -Xmn64m FullGCDemo

你也可以先自己獨立思考一下這塊程式碼問題何在。

CPU飆高

這是第一個現象，top命令就能看到，找到我們的行程ID，例如91782。然後執行命令 top-H-p91782檢視行程裡的執行緒情況：

1. PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                     
2. 91784 yyapp     20   0 2670m 300m  12m R 92.2  7.8   4:14.39 java                                                         
3. 91785 yyapp     20   0 2670m 300m  12m R 91.9  7.8   4:14.32 java                                                         
4. 91794 yyapp     20   0 2670m 300m  12m S  1.0  7.8   0:09.38 java                                                         
5. 91799 yyapp     20   0 2670m 300m  12m S  1.0  7.8   0:09.39 java

由這段結果可知執行緒91784和91785很消耗CPU。將91784和91785分別轉為16進位制，得到16688和16689。接下來透過執行命令命令 jstack-l91782>91782.log匯出執行緒棧資訊（命令中是行程ID），併在執行緒dump檔案中尋找16進位制數16688和16689，得到如下兩條資訊：

1. "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f700001e000 nid=0x16688 runnable 
2. "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f7000020000 nid=0x16689 runnable

由這兩行結果可知，消耗CPU的是ParallelGC執行緒。因為問題程式碼搭配的JVM引數沒有指定任何垃圾回收期，所以用的是預設的PS垃圾回收，所以這個JVM實體應該在頻繁FullGC，透過命令 jstat-gcutil917825s檢視GC表現可以驗證，由這段結果可知，Eden和Old都佔滿了，且不再發生YGC，但是卻在頻繁FGC，此時的應用已經不能處理任務，相當於假死了，好可怕：

1. S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT 
2.   0.00   0.00 100.00  99.98  78.57  83.36      5    0.633   366  327.647  328.281
3.   0.00   0.00 100.00  99.98  78.57  83.36      5    0.633   371  331.965  332.598
4.   0.00   0.00 100.00  99.98  78.57  83.36      5    0.633   376  336.996  337.629
5.   0.00   0.00 100.00  99.98  78.57  83.36      5    0.633   381  340.795  341.428
6.   0.00   0.00 100.00  99.98  78.57  83.36      5    0.633   387  346.268  346.901

揪出真兇

到這裡基本可以確認是有物件沒有釋放導致即使發生FullGC也回收不了引起的，準備dump進行分析看看Old區都是些什麼妖魔鬼怪，執行命令 jmap-dump:format=b,file=91782.bin91782，用MAT分析時，強烈建議開啟 keep unreachable objects：

接下來點選Actions下的Histogram，查詢大物件:

下麵貼出的是原圖，而不是筆者的Demo程式碼跑出來的：

由這段程式碼可知，大量的FutureContract和BigDecimal（說明：因為FutureContract中有多達16個BigDecimal型別的屬性），FutureContract佔了120MB，BigDecimal佔了95MB。那麼就可以斷定問題是與FutureContract相關的程式碼造成的，如果是正常的JVM示例，Histogram 試圖最佔記憶體的是byte[]和char[]兩個陣列，兩者合計一般會佔去80%左右的記憶體，遠遠超過其他物件佔用的記憶體。

接下來透過FutureContract就找到上面這塊buildBar方法程式碼，那麼為什麼是這塊程式碼無法釋放呢？單獨把這塊程式碼擰出來看看，這裡用到了ScheduledThreadPoolExecutor定時排程，且每3秒執行一次，然而定時器中需要的引數來自外面的 List，這就會導致 List這個物件一致被一個定時任務取用，永遠無法回收，從而導致FutureContract不斷晉升到Old區，直到佔滿Old區然後頻繁FullGC。

1. private static void buildBar(){
2.     List<FutureContract> futureContractList = getAllFutureContract();
3.     futureContractList.forEach(contract -> {
4.         // do something
5.         executor.scheduleWithFixedDelay(() -> {
6.             try{
7.                 doFutureContract(contract);
8.             }catch (Exception e){
9.                 e.printStackTrace();
10.             }
11.         }, 2, 3, TimeUnit.SECONDS);
12.     });
13. }

那麼為什麼會出現這種情況呢？我相信一個程式員不應該犯這樣的低階錯誤，後來看到原生程式碼，我做出一個比較合理的猜測，其本意可能是想透過呼叫 Executorexecutor來非同步執行，誰知小手一抖，在紅色框那裡輸入了taskExecutor，而不是executor：

解決問題

OK，知道問題的根因，想解決問題就比較簡單了，將taskExecutor改成executor即可：

1. private static ThreadPoolExecutor executor = new ThreadPoolExecutor(50, 50, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<>(128));
2. private static void buildBar(){
3.     List<FutureContract> futureContractList = getAllFutureContract();
4.     futureContractList.forEach(contract -> {
5.         // do something
6.         executor.execute(() -> {
7.             try{
8.                 doFutureContract(contract);
9.             }catch (Exception e){
10.                 e.printStackTrace();
11.             }
12.         });
13.     });
14. }

或者將這一塊直接改成同步處理，不需要執行緒池：

1. private static void buildBar(){
2.     List<FutureContract> futureContractList = getAllFutureContract();
3.     futureContractList.forEach(contract -> {
4.         // do something
5.         try{
6.             doFutureContract(contract);
7.         }catch (Exception e){
8.             e.printStackTrace();
9.         }
10.     });
11. }

 

往

期

精

彩

科普：String hashCode 方法為什麼選擇數字31作為乘子

哦，這就是java的優雅停機？（實現及原理）

好 RESTful API 的設計原則

資料庫最佳化的幾個階段

怎麼理解Condition?

如何擴充套件和最佳化執行緒池？

 

END

>>>>>> 加群交流技術 <<<<<<