天天看點
傳回

GC日志解讀，這次别再說看不懂GC日志了Serial GCParallel GCCMS GCG1 GC

測試環境：機器記憶體16G，JDK 8，12核CPU

測試用例，從網上找的示例，視情況修改即可：

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
/*
示範GC日志生成與解讀
*/
public class GCLogAnalysis {
    private static Random random = new Random();
    public static void main(String[] args) {
        // 目前毫秒時間戳
        long startMillis = System.currentTimeMillis();
        // 持續運作毫秒數; 可根據需要進行修改
        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
        // 結束時間戳
        long endMillis = startMillis + timeoutMillis;
        LongAdder counter = new LongAdder();
        System.out.println("正在執行...");
        // 緩存一部分對象; 進入老年代
        int cacheSize = 2000;
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此時間範圍内,持續循環
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾對象
            Object garbage = generateGarbage(100*1024);
            counter.increment();
            int randomIndex = random.nextInt(2 * cacheSize);
            if (randomIndex < cacheSize) {
                cachedGarbage[randomIndex] = garbage;
            }
        }
        System.out.println("執行結束!共生成對象次數:" + counter.longValue());
    }

    // 生成對象
    private static Object generateGarbage(int max) {
        int randomSize = random.nextInt(max);
        int type = randomSize % 4;
        Object result = null;
        switch (type) {
            case 0:
                result = new int[randomSize];
                break;
            case 1:
                result = new byte[randomSize];
                break;
            case 2:
                result = new double[randomSize];
                break;
            default:
                StringBuilder builder = new StringBuilder();
                String randomString = "randomString-Anything";
                while (builder.length() < randomSize) {
                    builder.append(randomString);
                    builder.append(max);
                    builder.append(randomSize);
                }
                result = builder.toString();
                break;
        }
        return result;
    }
}

Serial GC

JVM啟動參數：

GC日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(1083240k free), swap 33750228k(6246880k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 //初始化堆記憶體
-XX:MaxHeapSize=536870912     //最大堆記憶體
-XX:+PrintGC 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:-UseAdaptiveSizePolicy 
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops 
-XX:-UseLargePagesIndividualAllocation
-XX:+UseSerialGC 
----------------------Minor GC----------------------------
2021-09-09T14:44:04.813+0800: 0.163: [GC (Allocation Failure) 2021-09-09T14:44:04.813+0800: 0.163: 
[DefNew: 139776K->17472K(157248K), 0.0164545 secs] 139776K->45787K(506816K), 0.0165501 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 
2021-09-09T14:44:04.853+0800: 0.203: [GC (Allocation Failure) 2021-09-09T14:44:04.853+0800: 0.203:
[DefNew: 157248K->17471K(157248K), 0.0192998 secs] 185563K->84401K(506816K), 0.0193485 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
-----------------------Full GC----------------------------
2021-09-09T14:44:05.240+0800: 0.589: [GC (Allocation Failure) 2021-09-09T14:44:05.240+0800: 0.589: 
[DefNew: 157148K->157148K(157248K), 0.0000289 secs]2021-09-09T14:44:05.240+0800: 0.589: 
[Tenured: 341758K->308956K(349568K), 0.0459961 secs] 498907K->308956K(506816K),
[Metaspace: 2608K->2608K(1056768K)], 0.0460956 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
----------------------以下為将Xmx和Xms設定為256m後新産生的Full GC日志----------------------------------
2021-09-09T20:43:46.806+0800: 0.340: [GC (Allocation Failure) 2021-09-09T20:43:46.806+0800: 0.340: 
[DefNew: 69734K->69734K(78656K), 0.0000272 secs]2021-09-09T20:43:46.806+0800: 0.340: 
[Tenured: 167334K->174631K(174784K), 0.0251452 secs] 237068K->181953K(253440K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0253029 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 

2021-09-09T20:43:46.841+0800: 0.375: [Full GC (Allocation Failure) 2021-09-09T20:43:46.841+0800: 0.375: 
[Tenured: 174631K->174502K(174784K), 0.0228937 secs] 252975K->195967K(253440K),
[Metaspace: 2760K->2760K(1056768K)], 0.0230051 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

Minor GC日志解讀 

2021-09-09T14:44:04.813+0800: 0.163: [GC (Allocation Failure) 2021-09-09T14:44:04.813+0800: 0.163: 
[DefNew: 139776K->17472K(157248K), 0.0164545 secs]  139776K->45787K(506816K), 0.0165501 secs] [Times: user=0.00 sys=0.02, real=0.02 secs]
  • 2021-09-09T14:44:04.813-GC事件開始的時間點。+0800表示目前時區為東八區，這隻是一個辨別。0.163是GC事件相對于JVM啟動時間的間隔，機關是秒
  • GC - 用來區分Minor GC還是Full GC的标志。GC表明這是一次小型GC（Minor GC），即年輕代GC。Allocation Failure 表示觸發GC的原因。本次GC事件是由于對象配置設定失敗，即年輕代中沒有空間來存放新生成的對象引起的。
  • DefNew表示垃圾收集器的名稱。這個名稱表示：年輕到使用的單線程、标記-複制、STW的垃圾收集器。139776K->17472K 表示在垃圾收集之前和之後的年輕代使用量。(157248K) 表示年輕代的總空間大小。分析可得，GC之後年輕代使用率為11%。
  • 139776K->45787K 表示在垃圾收集前後整個堆記憶體的使用情況，(506816K)表示整個堆的大小
  • 0.0165501 secs - GC事件的持續時間，機關：秒
  • [Times: user=0.00 sys=0.02, real=0.02 secs] 表示此次GC事件的持續時間，通過三個部分來衡量：user 表示所有GC線程消耗的CPU時間；sys 表示系統調用和系統等待事件消耗的時間；real表示應用程式暫停的時間

總結

從上邊的日志中我們可以總結出，本次Minor GC造成系統延遲20ms，這個暫停時間對大部分系統來說都是可以接受的，但對某些延遲敏感的系統就不太理想了。

​

同時可以分析出JVM在GC事件中的記憶體使用以及變化情況，在此次垃圾收集之前，堆記憶體總使用量為139776K，其中年輕代使用了139776K。這很明顯表示GC之前老年代使用量為0（因為是第一次GC嘛，又沒有大對象）。

​

GC前後對比，年輕代的使用量為139776K->17472K，減少了122304K，但是堆記憶體的總使用量139776K->45787K隻減少了93989K，說明從年輕代提升到老年代的對象占122304K - 93989K = 28315K的記憶體空間，我們也可以通過另一種方式将GC後老年代的使用量算出來，就是GC後堆記憶體的使用量 - 年輕代的使用量 ---- 45787K - 17472K = 28315K。

分析下來，我們關注的主要是兩個資料：GC暫停時間，以及GC之後的記憶體使用量/使用率。

​

Full GC日志解讀

Full GC是針對新生代+老年代+方法區進行的垃圾回收

2021-09-09T14:44:05.240+0800: 0.589: [GC (Allocation Failure) 2021-09-09T14:44:05.240+0800: 0.589: 
[DefNew: 157148K->157148K(157248K), 0.0000289 secs]2021-09-09T14:44:05.240+0800: 0.589: 
[Tenured: 341758K->308956K(349568K), 0.0459961 secs] 498907K->308956K(506816K),
[Metaspace: 2608K->2608K(1056768K)], 0.0460956 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
----------------------以下為将Xmx和Xms設定為256m後新産生的Full GC日志----------------------------------
2021-09-09T20:43:46.806+0800: 0.340: [GC (Allocation Failure) 2021-09-09T20:43:46.806+0800: 0.340: 
[DefNew: 69734K->69734K(78656K), 0.0000272 secs]2021-09-09T20:43:46.806+0800: 0.340: 
[Tenured: 167334K->174631K(174784K), 0.0251452 secs] 237068K->181953K(253440K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0253029 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 

2021-09-09T20:43:46.841+0800: 0.375: [Full GC (Allocation Failure) 2021-09-09T20:43:46.841+0800: 0.375: 
[Tenured: 174631K->174502K(174784K), 0.0228937 secs] 252975K->195967K(253440K),
[Metaspace: 2760K->2760K(1056768K)], 0.0230051 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

首先看Xmx和Xms為512m下的Full GC日志

  • DefNew 157148K->157148K(157248K), 0.0000289 secs

     就不多講了，上邊已經講過了

  • Tenured

     : 用于清理老年代空間的垃圾收集器，

    Tenured

     表明使用的是單線程的STW垃圾收集器，使用的算法為

    标記-清除-整理算法

     ，

    341758K->308956K(349568K)

     表示 GC前後老年代的使用量，以及老年代的空間大小，

    0.0459961 secs

     是清理老年代使用的時間

  • 498907K->308956K(506816K)

     表示在GC前後整個堆記憶體部分的使用情況，以及可用的堆空間大小

  • Metaspace: 2760K->2760K(1056768K)

     表示元空間的變化情況，可以看出此次GC元空間沒有變化

  • Times: user=0.05 sys=0.00, real=0.05 secs

     上邊已經講過了，可以看到這次的GC暫停時間為50毫秒，比起年輕代的GC來說增加了一倍，這個時間與GC後存活對象的總數量關系最大

此次GC之後老年代的使用占比為308956K / 349568K = 88%，已經不算低了，但是也不能說明什麼問題，畢竟GC後内側使用量下降了，還需要後續的觀察。。

總結

FullGC主要關注GC後内側使用量是否下降，其次關注暫停時間，此次GC後老年代使用量大約為301MB左右，耗時50ms，如果記憶體擴大十倍，那耗時可能就是500ms甚至更高，系統就會有很明顯的影響了，這也就是說串行GC性能弱的一個原因，服務端一般是不會采用串行GC的。

​

再看Xmx和Xms設定為256m後新産生的Full GC，并沒有回收年輕代，隻是回收了老年代和元空間，這是為何呢？個人猜想是由于新生代沒有對象可回收并且老年代回收後也沒有空間存放新對象，是以JVM就不再回收新生代，而是收集老年代，為的是新生代的對象可以晉升到老年代中，從日志中可以看出，第二次Full GC之前的那次GC日志，年輕代使用率在GC前後沒有變化，并且老年代GC後使用率反而升高了達到了老年代容量， 才導緻的第二次無新生代的FullGC.

Parallel GC

Java啟動指令：

通過

-Xloggc:gc.log

将GC日志輸出到gc.log檔案中，詳細GC日志如下

---------------------第一部分------------------------------
Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16645364k(7836692k free), swap 19431936k(6065040k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:-UseAdaptiveSizePolicy
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:-UseLargePagesIndividualAllocation
-XX:+UseParallelGC
---------------------第二部分------------------------------
2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs] 
---------------------第三部分------------------------------
..........中間省略部分............
2021-09-09T22:08:14.214+0800: 0.403: [Full GC (Ergonomics) [PSYoungGen: 21497K->0K(153088K)] [ParOldGen: 333673K->249484K(349696K)] 355171K->249484K(502784K), [Metaspace: 2760K->2760K(1056768K)], 0.0326259 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 
..........中間省略部分............
---------------------第四部分------------------------------
Heap
 PSYoungGen      total 153088K, used 106759K [0x00000000f5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 131584K, 81% used [0x00000000f5580000,0x00000000fbdc1ca0,0x00000000fd600000)
  from space 21504K, 0% used [0x00000000fd600000,0x00000000fd600000,0x00000000feb00000)
  to   space 21504K, 0% used [0x00000000feb00000,0x00000000feb00000,0x0000000100000000)
 ParOldGen       total 349696K, used 331587K [0x00000000e0000000, 0x00000000f5580000, 0x00000000f5580000)
  object space 349696K, 94% used [0x00000000e0000000,0x00000000f43d0fb8,0x00000000f5580000)
 Metaspace       used 2766K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 307K, capacity 386K, committed 512K, reserved 1048576K

新生代Minor GC 

2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs]

  1. 2021-09-09T22:08:13.985+0800: 0.175

     代表GC發生的時間
  2. GC – 用來區分 Minor GC 還是 Full GC 的标志。這里是一次 小型GC(Minor GC)

  3. PSYoungGen

     ：垃圾收集器的名稱，這個名稱表示的是在年輕代中使用的：并行的

    标記-複制

     ，STW垃圾收集器，

  4. 153077K->21497K(153088K)

     表示年輕代回收前->回收後(年輕代記憶體大小)，GC後新生代使用率為 21497K / 153088K= 14%

  5. 446120K->355171K(502784K)

     表示堆記憶體回收前大小->堆記憶體回收後大小(堆記憶體大小)，GC後堆記憶體使用率為 355171K / 502784K = 70%，使用率并不低

  6. [Times: user=0.05 sys=0.11, real=0.01 secs]

     ：GC事件的持續時間，通過三個部分衡量，

    user

     表示GC線程所消耗的總CPU時間，

    sys

     表示作業系統和系統等待事件所消耗的時間，

    real

     則表示應用程式實際暫停時間。由于并不是所有的操作過程都能全部并行，是以在并行GC中，

    real約等于user+system/GC線程數

     。

​

通過這部分日志可以簡單計算出：

在GC之前，堆記憶體總使用量為

446120K

，其中年輕代為

153077K

，是以可以推算出回收前老年代使用量

293043K

；

在GC完成後，年輕代使用量減少了153077K- 21497K=131580K，總的堆記憶體減少了446120K - 355171K=90949K，年輕代減少了 14%，那麼可以計算出對象從新生代晉升到老年代131580K- 90949K= 40631K

是以GC完成後，老年代的使用量為293043 K + 40631K =273674K

老年代的大小為堆記憶體總量 - 年輕代總量 — 502784K - 153088K = 349696K ，使用率為 273674K / 349696K = 78%

​

總結

年輕代GC，我們可以關注暫停時間，以及GC後的記憶體使用率是否正常，但不用特别關注GC前的使用量，而且隻要業務在運作，年輕代的對象配置設定就少不了，回收量就不會減少

Full GC 

2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs] 

2021-09-09T22:08:14.214+0800: 0.403: 
[Full GC (Ergonomics) 
[PSYoungGen: 21497K->0K(153088K)] 
[ParOldGen: 333673K->249484K(349696K)] 355171K->249484K(502784K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0326259 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]

由于Full GC是對新生代+老年代的收集+方法區（元空間），是以GC日志中有新生代、老年代、元空間GC前後及記憶體大小展示。

  • Full GC

     是完全GC的标志，表明本次GC清理年輕代+老年代+方法區

  • PSYoungGen 21497K->0K(153088K)

     和上邊一樣，不作過多闡述

  • ParOldGen

     -用于清理老年代的垃圾收集器類型，在這裡使用的是名為ParOldGen的垃圾收集器，這是一款并行STW垃圾收集器，算法為

    标記-清除-整理

     。

    333673K->249484K

     GC前後老年代的記憶體使用量變化，

    (349696K)

     老年代總容量，GC之前老年代使用率為 333673K / 349696K = 95%，GC後老年代使用率為 71%，回收了不少，但是不能計算出有年輕代對象晉升了多少到老年代，因為老年代減少的使用量是被提升的記憶體抵消過的。

  • Metaspace: 2760K->2760K(1056768K)

     元空間并沒有被回收掉任何對象

  • 0.0326259 secs]

     表示GC事件持續的時間，機關：秒

  • Times: user=0.31 sys=0.00, real=0.03 secs

     ：與前邊講的相同

總結

FullGC與MinorGC的唯一差別就是增加了對老年代和方法區（元空間）的回收。

FullGC我們更關注老年代的使用量有沒有下降，以及下降了多少，如果FullGC之後記憶體使用率沒有下降并且還很高，那說明系統就有問題了

這裡我也把FullGC前一次的GC日志拿出來了，可以看到由于前一次的MinorGC後老年代使用率為78%，才導緻的FullGC。

堆記憶體分布

  • PSYoungGen total 75776K, used 63884K：年輕代占用75776K,，使用了63884K
    • eden space 65024K, 98% used，伊甸區占用了新生代65024K，其中98%被使用
    • from space 10752K, 0% used
    • to space 10752K, 0% used
  • ParOldGen total 180736K, used 180448K，老年代總共180736K，使用了180448K
  • Metaspace used 2766K, capacity 4486K, committed 4864K, reserved 1056768K：中繼資料區總計使用了2766K，容量是4486K，JVM保證可用的大小是4864K，保留白間1GB左右
    • class space used 307K, capacity 386K, committed 512K, reserved 1048576K，class space使用了307K，容量是386K

CMS GC

Java啟動指令

通過

-Xloggc:gc.log

将GC日志輸出到gc.log檔案中，詳細GC日志如下

--------------------------第一部分----------------------------------
Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(2966240k free), swap 40559696k(11356008k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912
-XX:MaxNewSize=178958336
-XX:MaxTenuringThreshold=6
-XX:NewSize=178958336 
-XX:OldPLABSize=16 
-XX:OldSize=357912576
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+UseConcMarkSweepGC
-XX:-UseLargePagesIndividualAllocation 
-XX:+UseParNewGC 
通過解析第一部分日志，我們可以看到，初始化堆記憶體大小與最大堆記憶體大小與并行GC是一樣的，指定-XX:+UseConcMarkSweepGC預設會加上-XX:+UseParNewGC作為新生代GC
--------------------------第二部分MinorGC----------------------------------
2021-09-10T10:04:53.039+0800: 0.312: [GC (Allocation Failure) 2021-09-10T10:04:53.039+0800: 0.312: 
[ParNew: 157248K->17472K(157248K), 0.0148265 secs] 321753K->222842K(506816K), 0.0148801 secs] [Times: user=0.03 sys=0.03, real=0.01 secs] 
--------------------------第三部分Major GC----------------------------------
2021-09-10T10:04:53.054+0800: 0.327: [GC (CMS Initial Mark) [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
---------------------------中間穿插着MinorGC-----------------------------
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs] 
2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441: [scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: [scrub string table, 0.0001136 secs][1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Minor GC 

2021-09-10T10:04:53.039+0800: 0.312: 
[GC (Allocation Failure) 2021-09-10T10:04:53.039+0800: 0.312: 
[ParNew: 157248K->17472K(157248K), 0.0148265 secs] 321753K->222842K(506816K), 0.0148801 secs] 
[Times: user=0.03 sys=0.03, real=0.01 secs]

前邊已經講過的内容不再重複，隻解析未解析過的内容

  • ParNew

     是垃圾收集器的名稱，對應的就是前邊列印的

    -XX:+UseParNewGC

     ，ParNew收集器是年輕代的垃圾收集器，用的是

    标記-複制

     算法，專門設計用來配合CMS垃圾收集器，

    157248K->17472K

     表示的是新生代GC前後使用量的變化，

    (157248K)

     是年輕代總大小。

    0.0148265 secs

     是消耗時間

  • 321753K->222842K(506816K)

     表示GC前後堆記憶體的使用量變化，以及堆記憶體的總大小，消耗時間是

    0.0148801 secs

  • Times: user=0.03 sys=0.03, real=0.01 secs

     ：表示GC的持續時間，real ~= (user + sys) / GC線程數

結果分析：

GC前，年輕代使用量為 100%，堆記憶體使用量為 63%，是以可以計算出老年代大小為

506816K - 157248 = 349568K

，GC前使用量為

321753K - 157428K = 164505K

老年代收的使用率為

164505 / 349568 = 47%

。

GC後，年輕代使用量為

17472K / 157248K

= 11%，下降了

139776K

，堆記憶體使用量為

222842K / 506816K

= 43% ，下降了

98911K

，兩值相減就是年輕代提升到老年代的對象大小：

40865K

，GC後老年代使用率為（ 164505K + 40865K ） / 349568K ~= 58%

Major GC 

2021-09-10T10:04:53.054+0800: 0.327: [GC (CMS Initial Mark) [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
==================================中間穿插着MinorGC================================
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
==================================================================================
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs] 
----------------------------------最終标記------------------------------------
2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) 
                                      [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: 
                                      [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: 
                                      [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: 
                                      [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441:
                                      [scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: 
                                      [scrub string table, 0.0001136 secs]
                                      [1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] 
                                      [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

這次MajorGC是緊接着前邊的MinorGC的，前一次MinorGC後Old區的使用率才58%，怎麼就觸發CMS MajorGC了呢，前邊在将CMS的時候明明說過觸發CMS GC的條件是達到了門檻值之後才會觸發，并且預設門檻值為92%，但是這裡才58%怎麼就觸發了呢？

​

原因我也去查了下，大家可以看這篇文章：JVM 源碼解讀之 CMS GC 觸發條件，這裡我也做下簡單解釋，是由于當我們沒有配置

UseCMSInitiatingOccupancyOnly

時，會根據統計資料動态判斷是否需要進行一次CMS GC，判斷邏輯是，如果預測CMS GC完成所需要的的時間大于預計老年代将要填滿的時間，則進行GC，這些判斷是需要曆史的CMS統計名額，然後第一次CMS GC時統計資料還沒有形成，這時會根據老年代的使用率來判斷是否要進行GC，答案就是50%

​

CMS相關介紹可以檢視我這篇文章：CMS垃圾收集器

​

接下來進行日志解析

​

階段1：初始标記

該階段是STW的階段，目的是标記所有的根對象包括根對象直接引用的對象，以及被年輕代中所有存活對象引用對象速度很快

2021-09-10T10:04:53.054+0800: 0.327:
[GC (CMS Initial Mark) 
 [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] 
 [Times: user=0.00 sys=0.00, real=0.00 secs]

  • GC (CMS Initial Mark)

     —這個階段的名稱為“ Initial Mark”

  • [1 CMS-initial-mark: 205370K(349568K)]

     表示老年代的使用量以及老年代的大小

  • 223428K(506816K), 0.0001030 secs

     –目前堆記憶體的使用量，以及可用的堆記憶體大小、GC消耗的時間，時間0.1毫秒，非常短，因為要标記的對象很少

  • [Times: user=0.00 sys=0.00, real=0.00 secs]

     –初始标記暫停的時間，可以看到被忽略不計了

階段2：并發标記

并發标記是從“初始标記”階段編輯的根元素開始，标記所有存活的對象，GC線程與使用者線程同時運作。

2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

  • CMS-concurrent-mark-start

     表明目前為CMS的并發标記階段

  • 0.003/0.003 secs

     -此階段的持續時間，分别是GC線程消耗的時間和實際消耗的時間

  • [Times: user=0.00 sys=0.00, real=0.00 secs]

     -對于并發階段來說這些時間并沒有多少意義，因為啥從并發标記時刻計算的，而這段時間應用程式也在執行，是以這個時間至少一個大概的值

階段3：并發預清理

此階段也是與使用者線程同時運作的，主要是來出來“并發标記”階段“髒卡”的老年代對象，為了減少Final Remark階段STW的時間，可通過

-XX:-CMSPrecleaningEnabled

關閉，預設開啟。

2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

與“并發标記”階段相同

​

階段4：可取消的并發預清理

具體此階段的流程這裡就不細講了，目的與“并發預清理”一樣，也是為了減少Final Remark階段STW的時間，在進入Final Remark階段前盡量等到一個Minor GC。具體的可以看我這篇CMS垃圾收集器。

2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
==================================中間穿插着MinorGC================================
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
==================================================================================
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs]

可以看到預清理過程中，發生了三次Minor GC。

​

階段5：最終标記

最終标記是CMS GC中的第二次STW，也是最後一次，該階段重新掃描堆中的對象，因為之前的預清理階段是并發執行的，有可能GC線程跟不上應用線程的修改速度，該階段需要掃描**新生代+GC Roots + 被标記為“髒區”的對象，**如果預清理階段沒有做好，這一步掃描新生代會非常耗時

2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) 
                                      [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: 
                                      [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: 
                                      [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: 
                                      [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441:
                                      [scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: 
                                      [scrub string table, 0.0001136 secs]
                                      [1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] 
                                      [Times: user=0.00 sys=0.00, real=0.00 secs]

  • CMS Final Remark

     -階段名稱，最終标記階段

  • YG occupancy: 20972 K (157248 K)

     - 目前年輕代的使用量和總容量

  • Rescan (parallel) , 0.0002117 secs

     - 在程式暫停後進行重新掃描，已完成存活對象的标記。并行執行，耗時

    0.0002117 secs

  • weak refs processing, 0.0000083 secs

     - 第一個子階段，處理弱引用，耗時

    0.0002117 secs

  • class unloading, 0.0002509 secs

     - 第二個子階段，解除安裝不使用的類，耗時

    0.0002509 secs

  • scrub symbol table, 0.0003192 secs

     - 第三個子階段，清理符号表，即持有class級别的metadata的符号表（symbol table）

  • 1 CMS-remark: 335528K(349568K)

     - 此階段完成後老年代的使用量和總容量

  • 356500K(506816K), 0.0009630 secs

     - 此階段完成整個堆記憶體的使用量和總容量，耗時

​

階段6：并發清除

此階段也是與使用者線程同時運作的，删除不再使用的對象，并回收他們占用的記憶體空間，由于是與使用者線程并發執行，是以可能會産生“浮動垃圾”

2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

與前邊的階段類似，不再講解

​

階段7：并發重置

此階段也是與使用者線程同時運作的，重置CMS算法相關的内部結構，下次觸發GC時就可以直接使用

2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

具體CMS GC後老年代記憶體使用量是多少這裡并不能分析出來，隻能通過後邊的Minor GC日志分析，例如本次CMS GC後的Minor GC日志如下

2021-09-10T11:20:07.151+0800: 0.615: 
[GC (Allocation Failure) 2021-09-10T11:20:07.151+0800: 0.615: 
 [ParNew: 157248K->17472K(157248K), 0.0123639 secs] 446745K->354158K(506816K), 0.0124328 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

計算出來老年代的使用率大約為83%，這個使用率并不度，說明了什麼問題呢，一般就是配置設定的記憶體小了，畢竟我們才指定了512M最大堆記憶體

​

Full GC

當并發模式失敗（Concurrent mod failure）會觸發Full GC。

  • **并發模式失敗：**CMS大部分階段是與使用者線程并發執行的，如果在執行垃圾收集時使用者線程建立的對象直接往老年代配置設定，但是沒有足夠的記憶體，就會報Concurrent mode failure
  • **晉升失敗：**新生代做Minor GC的時候，老年代沒有足夠的空間用來存放晉升的對象，則會報Concurrent mode failure；如果由于記憶體碎片問題導緻無法配置設定，就會報晉升失敗

可以看到下邊的日志，先發生了一次

concurrent mode failure

，後邊緊接着發生了一次Full GC

CMS2021-09-10T22:33:50.168+0800: 0.562: [CMS-concurrent-abortable-preclean: 0.000/0.017 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
 (concurrent mode failure): 331593K->349531K(349568K), 0.0564298 secs] 471258K->361742K(506816K), [Metaspace: 2760K->2760K(1056768K)], 0.0566131 secs] [Times: user=0.05 sys=0.00, real=0.06 secs] 
 
2021-09-10T22:33:50.246+0800: 0.640: [Full GC (Allocation Failure) 2021-09-10T22:33:50.246+0800: 0.640: [CMS: 349531K->349151K(349568K), 0.0528130 secs] 506497K->392533K(506816K), [Metaspace: 2760K->2760K(1056768K)], 0.0529324 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]

G1 GC

Java啟動指令

詳細GC日志如下

Java HotSpot(TM) 64-Bit Server VM (25.201-b09) for windows-amd64 JRE (1.8.0_201-b09), built on Dec 15 2018 18:36:39 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16657944k(1124124k free), swap 40559696k(8067960k free)
CommandLine flags: 
-XX:InitialHeapSize=536870912 
-XX:MaxHeapSize=536870912 
-XX:+PrintGC
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:-UseAdaptiveSizePolicy
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+UseG1GC
-XX:-UseLargePagesIndividualAllocation 

2021-09-10T14:31:56.590+0800: 0.429: [GC pause (G1 Evacuation Pause) (young), 0.0122670 secs]
   [Parallel Time: 2.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 437.9, Avg: 437.9, Max: 438.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.8, Max: 2.5, Diff: 2.3, Sum: 3.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 1.6, Max: 2.3, Diff: 2.3, Sum: 6.5]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.6]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.5, Avg: 2.6, Max: 2.6, Diff: 0.1, Sum: 10.4]
      [GC Worker End (ms): Min: 440.5, Avg: 440.5, Max: 440.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 9.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 25.0M(25.0M)->0.0B(21.0M) Survivors: 0.0B->4096.0K Heap: 31.2M(512.0M)->13.9M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
 
----------------------------------------------------------------------
    2021-09-10T14:31:57.007+0800: 0.846: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0130786 secs]
   [Parallel Time: 12.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 845.8, Avg: 845.9, Max: 846.0, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.6]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 11.8, Avg: 12.0, Max: 12.4, Diff: 0.6, Sum: 47.8]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 12.6, Avg: 12.7, Max: 12.8, Diff: 0.2, Sum: 50.6]
      [GC Worker End (ms): Min: 858.5, Avg: 858.6, Max: 858.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 118.0M(123.0M)->0.0B(161.0M) Survivors: 12.0M->17.0M Heap: 321.1M(512.0M)->221.0M(512.0M)]
 [Times: user=0.00 sys=0.06, real=0.01 secs] 


------------------------------------------------------------------
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-start]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-end, 0.0001075 secs]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-mark-start]
2021-09-10T14:31:57.023+0800: 0.861: [GC concurrent-mark-end, 0.0023080 secs]
2021-09-10T14:31:57.023+0800: 0.862: [GC remark 2021-09-10T14:31:57.023+0800: 0.862: [Finalize Marking, 0.0000914 secs] 2021-09-10T14:31:57.023+0800: 0.862: [GC ref-proc, 0.0000388 secs] 2021-09-10T14:31:57.023+0800: 0.862: [Unloading, 0.0003763 secs], 0.0008956 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC cleanup 232M->230M(512M), 0.0002672 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-start]
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-end, 0.0000103 secs]
---------------------------------------------------------------------
2021-09-10T14:31:57.063+0800: 0.902: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0028671 secs]
   [Parallel Time: 2.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 902.0, Avg: 902.2, Max: 902.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 0.8]
         [Processed Buffers: Min: 2, Avg: 4.0, Max: 8, Diff: 6, Sum: 16]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.7, Avg: 1.9, Max: 2.1, Diff: 0.4, Sum: 7.5]
      [GC Worker End (ms): Min: 904.1, Avg: 904.1, Max: 904.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.7 ms]
      [Evacuation Failure: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.0 ms]
   [Eden: 161.0M(161.0M)->0.0B(13.0M) Survivors: 17.0M->12.0M Heap: 439.1M(512.0M)->371.4M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
---------------------------------------------------------------------
    2021-09-10T14:31:57.069+0800: 0.908: [GC pause (G1 Evacuation Pause) (mixed), 0.0045144 secs]
   [Parallel Time: 4.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 908.2, Avg: 908.2, Max: 908.2, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.6]
      [Update RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8]
         [Processed Buffers: Min: 2, Avg: 3.8, Max: 5, Diff: 3, Sum: 15]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 3.7, Avg: 3.8, Max: 3.8, Diff: 0.1, Sum: 15.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 4.2, Avg: 4.2, Max: 4.2, Diff: 0.0, Sum: 16.8]
      [GC Worker End (ms): Min: 912.3, Avg: 912.4, Max: 912.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 13.0M(13.0M)->0.0B(48.0M) Survivors: 12.0M->4096.0K Heap: 389.0M(512.0M)->353.1M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
--------------------------------------------------------------------

Heap
 garbage-first heap   total 524288K, used 385426K [0x00000000e0000000, 0x00000000e0101000, 0x0000000100000000)
  region size 1024K, 4 young (4096K), 2 survivors (2048K)
 Metaspace       used 2614K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

以上為G1 GC的部分日志資訊，很少一部分。

​

在講解GC垃圾收集器的文章中，我們講過G1的垃圾收集分為兩個大部分，并且這兩部分可以相對獨立運作

  • 全局并發标記（Global Concurrent Marking）
  • 拷貝存活對象（Evacuation）

拷貝存活對象階段又分為兩種模式：

  • Yong模式
  • Mix模式

Evacuation Pause Yong（Yong 模式拷貝暫停）

從上邊的G1日志中我們就可以找到對應的這兩種模式:

GC pause (G1 Evacuation Pause) (young) (to-space exhausted)

，

GC pause (G1 Evacuation Pause) (mixed)

當年輕代空間用滿後，應用現場會被暫停，年輕代記憶體快中的存活對象被拷貝到存活區。如果還沒有存活區，則任意選擇一部分空閑的記憶體塊作為存活區。

2021-09-10T14:31:57.063+0800: 0.902: 
[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0028671 secs]
   [Parallel Time: 2.1 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 902.0, Avg: 902.2, Max: 902.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 0.8]
         [Processed Buffers: Min: 2, Avg: 4.0, Max: 8, Diff: 6, Sum: 16]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 1.7, Avg: 1.9, Max: 2.1, Diff: 0.4, Sum: 7.5]
      [GC Worker End (ms): Min: 904.1, Avg: 904.1, Max: 904.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.7 ms]
      [Evacuation Failure: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.0 ms]
   [Eden: 161.0M(161.0M)->0.0B(13.0M) 
    Survivors: 17.0M->12.0M 
    Heap: 439.1M(512.0M)->371.4M(512.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

  • GC pause (G1 Evacuation Pause) (young) (to-space exhausted)

     - G1轉移暫停，純年輕代模式，隻清理年輕代空間。這次暫停在JVM啟動之後902ms開始，持續的系統時間為

    0.0028671 secs

  • [Parallel Time: 2.1 ms, GC Workers: 4]

     - 表明後面的活動由4個Worker線程并行執行，消耗時間為2.1毫秒，worker是一種模式，類似于一個老闆指揮多個勞工幹活兒，中間的内容先不講，後邊會講解

  • [Code Root Fixup: 0.0 ms]

     - 釋放用于管理并行活動的内部資料，一般都接近于0，這個過程是串行的

  • [Code Root Purge: 0.0 ms]

     - 清理部分資料，也是非常快的，如非必要基本上等于0，也是串行的

  • [Other: 0.7 ms]

     - 其他活動消耗的時間，其中大部分是并行執行的，具體内容後邊會講解

  • [Eden: 161.0M(161.0M)->0.0B(13.0M)

     - 暫停之前和暫停之後，Eden區的使用量/總容量

  • Survivors: 17.0M->12.0M

     - GC暫停前後，存活區的使用量

  • Heap: 439.1M(512.0M)->371.4M(512.0M)]

     - 暫停前後整個堆記憶體的使用量/總容量

  • [Times: user=0.00 sys=0.00, real=0.00 secs]

     - GC事件的持續時間
    • 說明：系統時間是指一段程式從運作到終止，系統時鐘走過的時間，一般系統時間都要比CPU時間略長一些

Worker線程日志解讀

[GC Worker Start (ms): Min: 902.0, Avg: 902.2, Max: 902.4, Diff: 0.4]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
[Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 0.8]
[Processed Buffers: Min: 2, Avg: 4.0, Max: 8, Diff: 6, Sum: 16]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.3]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): Min: 1.7, Avg: 1.9, Max: 2.1, Diff: 0.4, Sum: 7.5]
[GC Worker End (ms): Min: 904.1, Avg: 904.1, Max: 904.1, Diff: 0.0]

  • GC Worker Start (ms)

     - GC的worker線程開始啟動時間，相對于pause開始時間的毫秒間隔。如果

    Min

     和

    Max

     差别很大，則表明本機其他程序所使用的線程數量過多，擠占了GC的可用CPU時間

  • [Ext Root Scanning (ms)

     - 用了來掃描對外記憶體（non - heap）的GC Root，如classloader，JNI引用，JVM系統ROOT等。後面顯示了運作時間，

    Sum

     指的是CPU時間

  • Update RS (ms)

     、

    Processed Buffers

     、

    Scan RS (ms)

     這三部分也是類似的，RS是Remember Set的縮寫，可以參考我之前寫的G1文章

  • Code Root Scanning (ms)

     - 掃描實際代碼中的root用了多長時間：例如線程棧中的局部變量

  • Object Copy (ms)

     - 用了多長時間來拷貝回收集中的存活對象

  • Termination (ms)

     - GC的worker線程用了多長時間來確定自身可用安全地停止，在這段時間内什麼也不做，完成後GC線程就終止運作了，是以叫終止等待時間

  • Termination Attempts

     - GC的worker線程嘗試多少次try 和terminate。如果worker發現還有一些任務沒處理完，則這一次嘗試就是失敗的，暫時還不能終止

  • GC Worker Other (ms)

     - 其他小的任務，因為時間很短，在GC日志将他們歸結在一起
  • GC Worker Total (ms) - GC的worker線程工作時間總計

  • GC Worker End (ms)

     - GC的worker線程完成作業時刻，相對于此次GC暫停開始時間的毫秒數。通常涞水這部分數字應該大緻相等，否則就說明有太多的線程呗挂起，很可能是因為“壞鄰居效應”所導緻的

Other日志解讀

[Evacuation Failure: 0.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.0 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 0.0 ms]

  • Evacuation Failure: 0.5 ms

     ：拷貝失敗耗時

  • Choose CSet

     ：選擇回收集耗時

  • Ref Proc

     - 處理強引用耗時，進行清理或者決定是否需要清理

  • Ref Enq: 0.0 ms

     - 用來将剩下的non - strong引用排列到合适的

    ReferenceQueue

     中

  • Humongous Register、Humongous Reclaim

     - 大對象相關的比分，後面介紹

  • Free CSet: 0.0 ms

     - 将回收集中被釋放的記憶體歸還所消耗的時間，釋放記憶體以便他們能用來配置設定新的對象

Concurrent Mark （并發标記）

當堆記憶體的總體使用比例達到一定數值時，就會觸發并發标記。這個預設比例是45%，可以通過參數

​

-XX:InitiatingHeapOccupancyPercent

來配置。和CMS一樣，G1的标記階段也是多階段部分并發的。

2021-09-10T14:31:57.007+0800: 0.846: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0130786 secs]
[Parallel Time: 12.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 845.8, Avg: 845.9, Max: 846.0, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.6]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 11.8, Avg: 12.0, Max: 12.4, Diff: 0.6, Sum: 47.8]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 1.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 12.6, Avg: 12.7, Max: 12.8, Diff: 0.2, Sum: 50.6]
      [GC Worker End (ms): Min: 858.5, Avg: 858.6, Max: 858.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 118.0M(123.0M)->0.0B(161.0M) Survivors: 12.0M->17.0M Heap: 321.1M(512.0M)->221.0M(512.0M)]
 [Times: user=0.00 sys=0.06, real=0.01 secs]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-start]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-end, 0.0001075 secs]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-mark-start]
2021-09-10T14:31:57.023+0800: 0.861: [GC concurrent-mark-end, 0.0023080 secs]
2021-09-10T14:31:57.023+0800: 0.862: [GC remark 2021-09-10T14:31:57.023+0800: 0.862: [Finalize Marking, 0.0000914 secs] 2021-09-10T14:31:57.023+0800: 0.862: [GC ref-proc, 0.0000388 secs] 2021-09-10T14:31:57.023+0800: 0.862: [Unloading, 0.0003763 secs], 0.0008956 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC cleanup 232M->230M(512M), 0.0002672 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-start]
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-end, 0.0000103 secs]

階段1：初始标記

可以在日志中看到

(initial-mark)

類似這種：

這次并發标記導緻的原因是大對象配置設定失敗，還可以看到

(yong)

字樣，由于G1的初始标記是借用Yong GC的暫停做的，可以看到下邊随之進行了一次Yong GC。

​

階段2：Root區掃描

此階段标記所有從“根區域”可達的存活對象。根區域包括：非空的區域，以及在标記過程中不得不收集的區域

2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-start]
2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-root-region-scan-end, 0.0001075 secs]

階段3：并發标記

在整個堆中查找标記可以通路的存活對象

2021-09-10T14:31:57.020+0800: 0.859: [GC concurrent-mark-start]
2021-09-10T14:31:57.023+0800: 0.861: [GC concurrent-mark-end, 0.0023080 secs]

階段4：重新标記

此階段是STW的，處理在并發标記階段剩餘未處理的SATB寫屏障的記錄，同時也處理弱引用。

2021-09-10T14:31:57.023+0800: 0.862:
[GC remark 2021-09-10T14:31:57.023+0800: 0.862: 
[Finalize Marking, 0.0000914 secs] 2021-09-10T14:31:57.023+0800: 0.862: 
[GC ref-proc, 0.0000388 secs] 2021-09-10T14:31:57.023+0800: 0.862: 
[Unloading, 0.0003763 secs], 0.0008956 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]

階段5：清理

清理和重置标記狀态，與mark - sweep中的sweep階段類似，但不是在堆上sweep實際對象，會統計每個Region被标記為活的對象有多少，這個階段如果發現完全沒有活對象的Region，就會将其整體回收到可配置設定Region清單中。

2021-09-10T14:31:57.024+0800: 0.863: [GC cleanup 232M->230M(512M), 0.0002672 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-start]
2021-09-10T14:31:57.024+0800: 0.863: [GC concurrent-cleanup-end, 0.0000103 secs]

标記周期一般隻在碰到Region中一個對象沒有的時候，才會順手處理一把，大多數情況下都不釋放記憶體。

Evacuation Pause Mix（混合模式） 

2021-09-10T14:31:57.069+0800: 0.908: [GC pause (G1 Evacuation Pause) (mixed), 0.0045144 secs]
[Parallel Time: 4.2 ms, GC Workers: 4]
   [GC Worker Start (ms): Min: 908.2, Avg: 908.2, Max: 908.2, Diff: 0.0]
   [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.6]
   [Update RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8]
      [Processed Buffers: Min: 2, Avg: 3.8, Max: 5, Diff: 3, Sum: 15]
   [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
   [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
   [Object Copy (ms): Min: 3.7, Avg: 3.8, Max: 3.8, Diff: 0.1, Sum: 15.0]
   [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
   [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
   [GC Worker Total (ms): Min: 4.2, Avg: 4.2, Max: 4.2, Diff: 0.0, Sum: 16.8]
   [GC Worker End (ms): Min: 912.3, Avg: 912.4, Max: 912.4, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.0 ms]
[Other: 0.2 ms]
   [Choose CSet: 0.0 ms]
   [Ref Proc: 0.0 ms]
   [Ref Enq: 0.0 ms]
   [Redirty Cards: 0.0 ms]
   [Humongous Register: 0.1 ms]
   [Humongous Reclaim: 0.0 ms]
   [Free CSet: 0.0 ms]
[Eden: 13.0M(13.0M)->0.0B(48.0M) Survivors: 12.0M->4096.0K Heap: 389.0M(512.0M)->353.1M(512.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs]

并發标記完成之後，G1将執行一次混合收集，不隻清理年輕代，還将收集統計出收益最高的若幹old區的Region。

​

簡單解讀：

  • Update RS (ms)

     - 因為RSet是并發處理的，必須確定在實際的垃圾收集之前，緩沖區中的card得到處理，如果card數量很多，則GC并發線程的負載可能就會很高

  • Processed Buffers

     - 各個worker線程處理了多少個本地緩沖區

  • Scan RS (ms)

     - 掃描RSet的引用耗費的時間

  • [Clear CT: 0.0 ms

     - 清理 Card Table中cards的時間。清理工作至上簡單地删除“髒”狀态，此狀态用來辨別一個字段是否被更新，供RSet使用

  • Redirty Cards

     - 将card table 中适當位置标記為dirty所花費的時間。“适當的位置”是由GC本身執行的堆記憶體改變所決定的，例如引用排隊等

Full GC

如果Mixed GC無法跟上程式配置設定記憶體的速度，導緻Old區域填滿無法配置設定記憶體時，就會切換到Serial GC來回收整個堆（Yong + Old + 方法區）

2021-09-10T22:28:58.211+0800: 0.899: 
[Full GC (Allocation Failure)  404M->389M(512M), 0.0213584 secs]
[Eden: 0.0B(25.0M)->0.0B(25.0M)
Survivors: 0.0B->0.0B 
Heap: 404.0M(512.0M)->389.3M(512.0M)], 
[Metaspace: 2760K->2760K(1056768K)]
jvm 垃圾收集器 gc
上一篇: 深入JVM系列（二）之GC機制、收集器與GC調優一、回顧JVM記憶體配置設定二、JVM的GC機制三、GC監視、收集器與GC調優四、GC調優的小例子
下一篇: JVM記憶體管理JVM記憶體管理

繼續閱讀