曹工雜談：手把手帶你讀懂 JVM 的 gc 日誌

三國夢迴發表於2019-07-23

JVMGC

一、前言

今天下午本來在划水，突然看到微信聯絡人那一個紅點點，看了下，應該是部落格園的朋友。加了後，這位朋友問了我一個問題：

問我，這兩塊有什麼關係？看到這段 gc 日誌，一瞬間腦子還有點懵，嗯，這個可能要翻下書了，周志明的 Java 虛擬機器那本神書裡面有講，我果斷地開啟了 pdf，找了起來，很快，找到了：

上面發的那個圖裡，6762k 就是新生代 gc 前的容量，1006k 就是新生代 gc 後的容量，9216k就是新生代的10m中（8m的eden區+1m的 from survivor區）的大小。

再看後面的那幾個數字，6762K-》3455K （19456K），意思就是，GC前，Java堆使用了 6762K，GC後，Java堆使用了 3455K，而19456K就是整個堆的容量（新生代9m+老年代10m）。

按理說，這麼解釋就足夠了，但是，眼尖，他提出了下面的問題（大概意思是這個，我自己配的字）：

這他麼就尷尬了。。。怎麼都解釋不通了啊。。。書上怕不是錯了啊。。。經過我們一番研究，得出一致結論：

網上搜了下，感覺都是些理論，感覺大家都沒問題，就我有問題？？？想起之前看虎撲帖子，有人發帖說浙江很富，沒有窮人（確實富），有浙江網友回覆：浙江就我一個窮人！

我現在就是那個感覺，大家都沒問題，就我有問題？？

當然，如果我就此止步了，也就不會寫這個了，我和那位朋友搗鼓了一下，還是理解清楚了 gc 日誌。

二、gc 日誌的正確閱讀方法

友情提示：大家跑不出來和我一樣效果的話，記得看看自己打斷點了沒。

找這位朋友拿了他的測試程式碼，很簡單的demo，如下：

 1 import java.util.concurrent.TimeUnit;
 2 
 3 
 4 public class AllocationTest {
 5 
 6     public static final int _1MB = 1024 * 1024;
 7 
 8 
 9     public static void main(String[] args) throws InterruptedException {
10         byte[] allocation1, allocation2, allocation3, allocation4;
11 
12         allocation1 = new byte[2 * _1MB];
13         allocation2 = new byte[2 * _1MB];
14         allocation3 = new byte[2 * _1MB];
15         //觸發Minor GC
16         allocation4 = new byte[4 * _1MB];
17     }
18 }

JVM引數如下：

 -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8

我本地先跑了下，結果是下面這樣的：

這個console，和這位朋友的也不一致，我這邊連那行 gc 前後的堆大小的日誌都沒打。因為他發我的引數裡，可以看出來，沒有指定垃圾收集器，那就是用了預設垃圾收集器。而預設的垃圾收集器在不同版本的電腦上、不同版本的 JVM 上可能不一致。為了方便統一認識，我就建議大家統一用 Serial new 收集器，於是加了下面引數：

-verbose:gc -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8

這次再執行，確實可以列印出來了

這裡，只是重現了和這位朋友一樣的問題，但問題本身，還沒解決.。基於有問題就DEBUG的習慣，在下面這行打了個斷點：

 1 import java.util.concurrent.TimeUnit;
 2 
 3 public class AllocationTest {
 4 
 5     public static final int _1MB = 1024 * 1024;
 6 
 7     public static void main(String[] args) throws InterruptedException {
 8         byte[] allocation1, allocation2, allocation3, allocation4;
 9 
10         allocation1 = new byte[2 * _1MB];
11         allocation2 = new byte[2 * _1MB];
12         allocation3 = new byte[2 * _1MB];
13         //觸發Minor GC
14         allocation4 = new byte[4 * _1MB];
15 
16         TimeUnit.SECONDS.sleep(100);
17     }
18 }

在16行打了個斷點，斷點停在 16 行以後，console 如下：

讓我驚醒的是，這次只打了這一行，並沒有列印下圖這部分：

其實這裡已經可以分析出來 gc 的大體過程了，不過為了方便我們理解，我們可以加上以下 JVM 引數：

-verbose:gc -XX:+UseSerialGC -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+PrintGC  -XX:+PrintGCTimeStamps  -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintGCApplicationStoppedTime

這次，斷點依然如約停在了那一行，我們看看 console，首先，下面是 gc 前的堆佔用情況

然後，看看 gc 後的情況：

這裡，我們就可以看出來了，那3個 2m 大的物件，一開始佔用了 eden區，eden區總共只有8m，那就只剩2m（實際上沒剩2m，因為jvm自己佔了一部分），這時候，我們要分配一個 4m 大的物件，那，JVM 在收到這個分配 4m 記憶體的請求後，檢查了自身的 eden區，明顯不夠，那就 gc 吧，也沒啥好gc 的，那三個2m的物件，生命週期還沒結束，我們當前的執行緒堆疊還維持著對它們的強引用，肯定是沒法回收了。 3個 2m 的物件，活過本次gc，本來要放到 to survivor 區，但是明顯放不下，於是只好丟給老年代了。

於是，老年代被佔用了 6m 空間。

理清了上述過程，再看下面那行gc 日誌：