JAVA GC日誌分析

幻_發表於2019-06-07
JavaGC

這裡以Java8為例

GC環境模擬

首先我們給出如下程式碼用來觸發GC

public static void main(String[] args) {
    // 每100毫秒建立100執行緒，每個執行緒建立一個1M的物件，即每100ms申請100M堆空間
    Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
        for (int i = 0; i < 100; i++) {
            new Thread(() -> {
                try {
                    //  申請1M
                    byte[] temp = new byte[1024 * 1024];
                    Thread.sleep(new Random().nextInt(1000)); // 隨機睡眠1秒以內
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }).start();
        }
    }, 1000, 100, TimeUnit.MILLISECONDS);
}
複製程式碼

我們要模擬的場景是年輕代不斷地Young GC，並有一部分物件晉升到老年代，當老年代空間不足時觸發Full GC。

程式邏輯：每100毫秒建立100個執行緒，每個執行緒建立一個1M的物件，即每100ms申請100M堆空間。之所以每個執行緒隨機睡眠1s，是為了避免物件朝生夕滅，保證可以有一部分物件能晉升到老年代，更好的觸發Young GC 和 Full GC，注意這個睡眠時間如果大了，會導致OOM，如果小了，很難觸發FULL GC。

虛擬機器引數解釋

啟動Java程式：java -Xms200m -Xmx200m -Xmn100m -verbose:gc -XX:+PrintGCDetails -Xloggc:./gc.log -XX:+PrintGCDateStamps -jar demo-0.0.1-SNAPSHOT.jar

-Xms200m -Xmx200m 最小/最大堆記憶體 200M

-Xmn100m 年輕代記憶體 100M

-verbose:gc 開啟GC日誌

-XX:+PrintGCDetails -Xloggc:./gc.log -XX:+PrintGCDateStamps 將GC日誌詳情輸入到gc.log中

jmap分析

jcmd 獲取我們Java程式的Id：6264

jmap -heap 6264檢視堆資訊

第一次檢視，我們發現 Eden區是98M，S0、S1是1M

JAVA GC日誌分析

第二次檢視， Eden區是99M，S0、S1是0.5M

JAVA GC日誌分析

Eden區與Survivor區的比例在動態的變化，並不是預設的8:1:1。

原來我們使用預設的垃圾收集器Parallel Scavenge+Parallel Old組合，而該收集器下-XX:+UseAdaptiveSizePolicy是預設開啟的，即Eden區與Survivor區比例根據GC情況會自適應變化。

我們加上引數，關閉年輕代自適應，年輕代比例設定為8:1:1

-XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=8

另外為了儘早的觸發FULL GC，我們新增虛擬機器引數

-XX:MaxTenuringThreshold=10

晉升年齡由預設的15修改為10，使得年輕代的物件更容易晉升到老年代

重啟虛擬機器檢視jmap

JAVA GC日誌分析

年輕代

  • Eden區80M 已使用51M，當前使用率63.8%

  • S0區10M 已使用0.43M，使用率4.37%

  • S1區10M 使用率為空

老年代

  • 100M 已使用18.39M，使用率18.9%

GC日誌內容分析

檢視我們輸出的GC日誌gc.log，選取其中兩段

2019-06-09T02:55:30.993+0800: 330.811: [GC (Allocation Failure) [PSYoungGen: 82004K->384K(92160K)] 184303K->102715K(194560K), 0.0035647 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-06-09T02:55:30.997+0800: 330.815: [Full GC (Ergonomics) [PSYoungGen: 384K->0K(92160K)] [ParOldGen: 102331K->5368K(102400K)] 102715K->5368K(194560K), [Metaspace: 16941K->16914K(1064960K)], 0.0213953 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

Young GC

[GC (Allocation Failure) [PSYoungGen: 82004K->384K(92160K)] 184303K->102715K(194560K), 0.0035647 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

解釋:

  • 年輕代GC：[GC前年輕代80.08M->GC後0.37M(年輕代總大小90M)]GC前堆179.98M->GC後堆100.3M(堆總大小190M)，用時]

  • 其中年輕代總大小是90M而不是100M，這裡我理解是年輕代當前最大申請到90M

  • 100M*80%=80M 是Eden區大小

  • 80M*80% = 64M Eden區預設佔用超過8成即64M就會觸發YoungGC

Full GC

[Full GC (Ergonomics) [PSYoungGen: 384K->0K(92160K)] [ParOldGen: 102331K->5368K(102400K)] 102715K->5368K(194560K), [Metaspace: 16941K->16914K(1064960K)], 0.0213953 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

解釋：

  • [GC前年輕代0.375M->GC後年輕代0M(年輕代總大小90M)][GC前老年代99.93M->GC後老年代5.24M(老年代總大小100M)]GC前堆100.3M->GC後堆5.24M（堆總大小190M）,[後設資料區:GC前16.5,GC後16.5(後設資料區總大小1040M)]，用時]

  • 可以推測出此次FullGC原因是年輕代晉升老年代空間不足導致

利用視覺化工具分析

這裡我們利用 gceasy.io/ 分析一下

(1)統計年輕代、老年代、後設資料區最大可用空間以及峰值，這裡後設資料區大小在我們的虛擬機器引數沒有配置，所以取的是預設值1040M

JAVA GC日誌分析

(2)吞吐量、GC平均延遲、最大延遲以及延遲區間的統計

JAVA GC日誌分析

(3)堆所用大小的實時分析，紅色位置是發生了FullGC使得堆總量直線下降

JAVA GC日誌分析
會發現虛擬機器在剛啟動不久的階段觸發大量的FULL GC，我的理解是我們申請的物件都隨機睡眠一秒以內，剛啟動時大部分還存線上程的引用，GCRoot可達。在剛啟動的時候觸發FULL GC並不會完整清理掉老年代空間並由於空間不足不斷觸發FULL GC。

(4)GC空間總量和時間的統計

JAVA GC日誌分析

(5)各類GC時間、GC次數、GC總量等指標

JAVA GC日誌分析

總結

GC日誌分析可以幫助我們巨集觀的監控GC執行情況。一方面如果頻繁的FullGC會有嚴重的效能問題(STW)，另一方面過於頻繁的GC，即GC佔用系統正常執行的比重過多，吞吐量低，則是一定程度上的效能資源浪費。若系統存在效能問題，根據GC分析各項指標的作為參考，我們也可以適當的在程式裡或虛擬機器引數做些調優。

相關文章