GC日志解读，这次别再说看不懂GC日志了

壹氿
9,254 阅读44分钟

测试环境：机器内存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启动参数：

java -Xmx512m -Xms512m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseSerialGC -XX:-UseAdaptiveSizePolicy GCLogAnalysis

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启动命令：

java -Xmx512m -Xms512m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseParallelGC -XX:-UseAdaptiveSizePolicy GCLogAnalysis

通过-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->249484KGC前后老年代的内存使用量变化，(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启动命令

java  -XX:+UseConcMarkSweepGC  -Xmx512m -Xms512m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps GCLogAnalysis

通过-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启动命令

java  -XX:+UseG1GC  -Xmx512m -Xms512m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:-UseAdaptiveSizePolicy GCLogAnalysis

详细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的部分日志信息，很少一部分。
​

在讲解G1垃圾收集器的文章中，我们讲过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)类似这种：

2021-09-10T14:31:57.007+0800: 0.846: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0130786 secs]

这次并发标记导致的原因是大对象分配失败，还可以看到(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)]
avatar
文章
阅读
粉丝
相关推荐
终于弄明白了 RocketMQ 的存储模型
4.8k阅读
 · 
15点赞
动态线程池组件-设计与实现
4.6k阅读
 · 
61点赞
基于Netty高性能RPC框架（分布式缓存、幂等性、雪花算法）
2.9k阅读
 · 
6点赞
ES 深分页问题解决方案
5.9k阅读
 · 
16点赞
聊聊多个节点实例数据同步如何触发
560阅读
 · 
1点赞
手写SOFA-JRAFT：单主复制在raft共识算法中的实现(一)
232阅读
 · 
1点赞
JVM技术之旅-了解分析内存布局区域
1.1k阅读
 · 
4点赞
spring事件监听（eventListener)
2.3k阅读
 · 
0点赞
数据齐舞：深入浅出分布式事务的八奇技
244阅读
 · 
8点赞