[转帖]GC日志解读，这次别再说看不懂GC日志了

转载

jinanxiaolaohu6 2024-01-09 11:06:00

文章标签 老年代 java Time 文章分类 JavaScript 前端开发

测试环境：机器内存16G，JDK 8，12核CPU

测试用例，从网上找的示例，视情况修改即可：

java

复制代码

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

复制代码

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

GC日志如下：

java

复制代码

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日志解读

java

复制代码

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是针对新生代+老年代+方法区进行的垃圾回收

java

复制代码

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

复制代码

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

通过-Xloggc:gc.log将GC日志输出到gc.log文件中，详细GC日志如下

java

复制代码

---------------------第一部分------------------------------
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

java

复制代码

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:13.985+0800: 0.175代表GC发生的时间
GC – 用来区分 Minor GC 还是 Full GC 的标志。这里是一次小型GC(Minor GC)
PSYoungGen：垃圾收集器的名称，这个名称表示的是在年轻代中使用的：并行的标记-复制，STW垃圾收集器，
153077K->21497K(153088K)表示年轻代回收前->回收后(年轻代内存大小)，GC后新生代使用率为 21497K / 153088K= 14%
446120K->355171K(502784K)表示堆内存回收前大小->堆内存回收后大小(堆内存大小)，GC后堆内存使用率为 355171K / 502784K = 70%，使用率并不低
[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

java

复制代码

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

复制代码

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

通过-Xloggc:gc.log将GC日志输出到gc.log文件中，详细GC日志如下

java

复制代码

--------------------------第一部分----------------------------------
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

java

复制代码

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

java

复制代码

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的阶段，目的是标记所有的根对象包括根对象直接引用的对象，以及被年轻代中所有存活对象引用对象速度很快

java

复制代码

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线程与用户线程同时运行。

java

复制代码

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关闭，默认开启。

java

复制代码

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垃圾收集器。

java

复制代码

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 + 被标记为“脏区”的对象，**如果预清理阶段没有做好，这一步扫描新生代会非常耗时

java

复制代码

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：并发清除
此阶段也是与用户线程同时运行的，删除不再使用的对象，并回收他们占用的内存空间，由于是与用户线程并发执行，因此可能会产生“浮动垃圾”

java

复制代码

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时就可以直接使用

java

复制代码

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日志如下

java

复制代码

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

java

复制代码

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

复制代码

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

详细GC日志如下

java

复制代码

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]