写在前面

本文一起看下如何查看GC日志。

1：环境准备

为了能更模拟真实的业务环境生成GC日志，我们首先来准备一个测试类，详细的注释已经在代码中，如下：

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;
        // 这里定义一个数组，这里cachedGarbage就是gc root,这样在方法栈帧弹出方法栈之前，其所引用的对象都是
        // GC ROOT 可达的
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此时间范围内,持续循环
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾对象
            Object garbage = generateGarbage(100*1024);
            counter.increment();
            // 这里生成4000以内的数字，则有一半的概率randomIndex < cacheSize为true，则该对象
            // 存储到数组中，经过young GC会晋升到老年代，并且如果是后续运行生成了相同的2000以内的值
            // 则之前的会被盖掉，即变为垃圾对象，就模拟了老年代垃圾被回收的场景
            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;
    }
}

1.1：需要用到的参数

-XX:+PrintGCDetails
    打印GC的详细日志
-XX:+PrintGC 
    打印GC的简单信息，比PrintGCDetails信息少
-Xloggc:filename
    将GC日志写到文件，以便于之后的分析，默认写到标准输出
-XX:+PrintGCTimeStamps
    GC日志打印时间戳

1.2：对内存默认的大小

当总内存小于1g时，默认使用总内存的二分之一，当总内存大于1g时，默认使用总内存的四分之一。

1.3：各种GC傻傻分不清楚

我们经常听到有人说，young GC，也有听说minor GC，或者是FULL GC，major GC，他们是什么关系呢？其实young GC和minor GC（小型GC），都是指对年轻代的GC,FULL GC 和major GC（大型GC）都是指对整个堆内存即young+old的GC，如下图：

2：不同GC测试

2.1：Java8 1g 并行GC

这里我们不指定具体使用什么GC，则默认使用的就是parallel GC，如下：

D:\test>D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx1g -Xms1g -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:d:\\test\\gc1423.log -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
执行结束!共生成对象次数:14339

我们来分析下主要的GC日志：

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for windows-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 19:54:30 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16568620k(4324356k free), swap 33345836k(14847436k free) -- 页大小4k，物理内存16g，空闲4g
CommandLine flags: -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC -- 启动jvm的参数，注意-XX:+UseParallelGC 说明使用的parallel GC
// 2023-05-24 14:28:01
2023-05-24T14:24:33.383+0800: 0.148: [GC (Allocation Failure) [PSYoungGen: 262144K->43513K(305664K)] 262144K->83258K(1005056K), 0.0147874 secs] [Times: user=0.06 sys=0.09, real=0.01 secs] 
2023-05-24T14:24:33.431+0800: 0.197: [GC (Allocation Failure) [PSYoungGen: 305657K->43518K(305664K)] 345402K->156146K(1005056K), 0.0197271 secs] [Times: user=0.20 sys=0.11, real=0.02 secs] 
2023-05-24T14:24:33.486+0800: 0.251: [GC (Allocation Failure) [PSYoungGen: 305662K->43517K(305664K)] 418290K->227355K(1005056K), 0.0197875 secs] [Times: user=0.05 sys=0.09, real=0.02 secs] 
2023-05-24T14:24:33.536+0800: 0.302: [GC (Allocation Failure) [PSYoungGen: 305488K->43512K(305664K)] 489325K->299959K(1005056K), 0.0201243 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 
2023-05-24T14:24:33.586+0800: 0.352: [GC (Allocation Failure) [PSYoungGen: 305656K->43514K(305664K)] 562103K->373466K(1005056K), 0.0208103 secs] [Times: user=0.25 sys=0.06, real=0.02 secs] 
2023-05-24T14:24:33.634+0800: 0.400: [GC (Allocation Failure) [PSYoungGen: 305658K->43514K(160256K)] 635610K->452144K(859648K), 0.0211340 secs] [Times: user=0.23 sys=0.05, real=0.02 secs] 
2023-05-24T14:24:33.670+0800: 0.435: [GC (Allocation Failure) [PSYoungGen: 159655K->70207K(232960K)] 568285K->487021K(932352K), 0.0085462 secs] [Times: user=0.16 sys=0.00, real=0.01 secs] 
2023-05-24T14:24:33.698+0800: 0.463: [GC (Allocation Failure) [PSYoungGen: 186871K->98364K(232960K)] 603686K->524790K(932352K), 0.0186767 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 
2023-05-24T14:24:33.730+0800: 0.496: [GC (Allocation Failure) [PSYoungGen: 215100K->112561K(232960K)] 641526K->556737K(932352K), 0.0217657 secs] [Times: user=0.13 sys=0.02, real=0.02 secs] 
2023-05-24T14:24:33.766+0800: 0.532: [GC (Allocation Failure) [PSYoungGen: 228947K->71653K(232960K)] 673122K->579879K(932352K), 0.0223997 secs] [Times: user=0.06 sys=0.09, real=0.02 secs] 
2023-05-24T14:24:33.802+0800: 0.568: [GC (Allocation Failure) [PSYoungGen: 188389K->39862K(232960K)] 696615K->610839K(932352K), 0.0175821 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 
2023-05-24T14:24:33.832+0800: 0.598: [GC (Allocation Failure) [PSYoungGen: 156598K->39803K(232960K)] 727575K->642912K(932352K), 0.0124792 secs] [Times: user=0.13 sys=0.03, real=0.01 secs] 
2023-05-24T14:24:33.845+0800: 0.611: [Full GC (Ergonomics) [PSYoungGen: 39803K->0K(232960K)] [ParOldGen: 603109K->335145K(699392K)] 642912K->335145K(932352K), [Metaspace: 2685K->2685K(1056768K)], 0.0623412 secs] [Times: user=0.63 sys=0.00, real=0.06 secs] 
...
Heap
 PSYoungGen      total 232960K, used 42685K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 116736K, 4% used [0x00000000eab00000,0x00000000eafe93a8,0x00000000f1d00000)
  from space 116224K, 32% used [0x00000000f1d00000,0x00000000f41c6398,0x00000000f8e80000)
  to   space 116224K, 0% used [0x00000000f8e80000,0x00000000f8e80000,0x0000000100000000)
 ParOldGen       total 699392K, used 421624K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
  object space 699392K, 60% used [0x00000000c0000000,0x00000000d9bbe198,0x00000000eab00000)
 Metaspace       used 2691K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 291K, capacity 386K, committed 512K, reserved 1048576K

2023-05-24 14:28:01处是发生了第一次的young GC，来看下：

2023-05-24T14:24:33.383+0800: 0.148: [GC (Allocation Failure) [PSYoungGen: 262144K->43513K(305664K)] 262144K->83258K(1005056K), 0.0147874 secs] [Times: user=0.06 sys=0.09, real=0.01 secs] 
2023-05-24T14:24:33.383+0800：
    发生GC的时间
GC (Allocation Failure)：
    触发young GC的原因
PSYoungGen: 262144K->43513K(305664K)：
    年轻代GC前总内存占用量是262144K，GC后总内存占用量是43513，即年轻代的内存占用减少了262144K-43513=218,631，即减少了218M，young总内存的大小是305664K。
262144K->83258K(1005056K)：
    总内存占用量从262144K（注意此时总内存占用量和young内存占用量是相等的，因为此时old还没有对象，所有对象在young），减少到了83258K,总的内存减少量是262144-83258=178,886，即178M,注意到，年轻代减少了218M，总内存减少了178M，剩下的218M-178M=40M的对象并没有从内存中清理掉，而是晋升到老年代了。堆内存总大小是1005056K。
    补充下对象进入老年代的条件：
    1：经历了-XX:MaxTenuringThreashold=x 默认x的值是15
    2：单个对象大小超过了-XX:PreTenureSizeTheshold=xM 这里x默认为1M，即当对象的大小超过1M时直接进入老年代
    3：存活的对象总大小超过了s区大小，则直接进入老年代，即空间担保机制。
    我们这里的40M数据进入老年代就是触发了空间担保机制，因为总内存大小1024M,所以young区大小是1024*(1:3)=338M 而eden:s0:sq=8:1:1，所以s区大小是338M*(1:10)=33.8M，而33.8M小于产生的垃圾对象大小40M，所以全部晋升到老年代了。
0.0147874 secs：
    young GC的时长是14.7ms，速度还是比较快的
Times: user=0.06 sys=0.09, real=0.01 secs：
    GC使用的CPU时间 

以上GC前和GC后的对象分布如下图：

之后又发生了11次，统共发生了12次young GC，接着发生一次FULL GC,如下：

2023-05-24T14:24:33.845+0800: 0.611: [Full GC (Ergonomics) [PSYoungGen: 39803K->0K(232960K)] [ParOldGen: 603109K->335145K(699392K)] 642912K->335145K(932352K), [Metaspace: 2685K->2685K(1056768K)], 0.0623412 secs] [Times: user=0.63 sys=0.00, real=0.06 secs] 

Full GC (Ergonomics):
    发生了FULLGC
PSYoungGen: 39803K->0K(232960K)
    GC前young内存占用大小为39803K,GC后变为0
ParOldGen: 603109K->335145K(699392K)：
    GC前old内存总占用603109K，GC后总占用335145K
642912K->335145K(932352K)
    GC前总内存是642912K，GC后总内存是335145K，注意因为GC后只有old有对象，所以这里GC后和old GC后的大小是一致的
Metaspace: 2685K->2685K(1056768K)
    元数据区没有变化
0.0623412 secs：
    FULlGC的时长是62.3ms，速度也还行

FULL GC前后内存占用对比如下图：

接着我们尝试配置512M内存看下：

$ D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx512m -Xms512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:d:\\test\\gc1423.log -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
执行结束!共生成对象次数:7975

JHP+Administrator@jhp MINGW64 /d/test
$ cat gc1423.log | grep 'GC (Allocation Failure' | wc -l
25

JHP+Administrator@jhp MINGW64 /d/test
$ cat gc1423.log | grep 'Full GC' | wc -l
10

可以看到young GC和FULL GC的次数都增多了，接着我们改成256m试下：

$ D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx256m -Xms256m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:d:\\test\\gc1701.log -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at GCLogAnalysis.generateGarbage(GCLogAnalysis.java:55)
        at GCLogAnalysis.main(GCLogAnalysis.java:27)

直接发生了oom，在oom前发生了很多次的FULL GC，可以通过日志看下：

2023-05-24T16:59:49.005+0800: [Full GC (Ergonomics) [PSYoungGen: 29654K->18666K(58368K)] [ParOldGen: 174909K->174894K(175104K)] 204563K->193560K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0346551 secs] [Times: user=0.27 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.040+0800: [Full GC (Ergonomics) [PSYoungGen: 29657K->20246K(58368K)] [ParOldGen: 174894K->174805K(175104K)] 204552K->195052K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0284192 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.070+0800: [Full GC (Ergonomics) [PSYoungGen: 29474K->21399K(58368K)] [ParOldGen: 174805K->175068K(175104K)] 204280K->196467K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0290946 secs] [Times: user=0.30 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.101+0800: [Full GC (Ergonomics) [PSYoungGen: 29386K->20489K(58368K)] [ParOldGen: 175068K->174671K(175104K)] 204455K->195161K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0340875 secs] [Times: user=0.16 sys=0.03, real=0.03 secs]
2023-05-24T16:59:49.137+0800: [Full GC (Ergonomics) [PSYoungGen: 29645K->22865K(58368K)] [ParOldGen: 174671K->174844K(175104K)] 204316K->197710K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0338009 secs] [Times: user=0.16 sys=0.02, real=0.03 secs]
2023-05-24T16:59:49.172+0800: [Full GC (Ergonomics) [PSYoungGen: 29668K->24502K(58368K)] [ParOldGen: 174844K->174435K(175104K)] 204512K->198937K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0260702 secs] [Times: user=0.23 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.199+0800: [Full GC (Ergonomics) [PSYoungGen: 29696K->26267K(58368K)] [ParOldGen: 174435K->174573K(175104K)] 204131K->200840K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0318971 secs] [Times: user=0.27 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.232+0800: [Full GC (Ergonomics) [PSYoungGen: 29541K->27211K(58368K)] [ParOldGen: 174573K->174306K(175104K)] 204114K->201518K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0221968 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
2023-05-24T16:59:49.255+0800: [Full GC (Ergonomics) [PSYoungGen: 29600K->26935K(58368K)] [ParOldGen: 174306K->175102K(175104K)] 203907K->202038K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0207386 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
2023-05-24T16:59:49.276+0800: [Full GC (Ergonomics) [PSYoungGen: 29685K->28246K(58368K)] [ParOldGen: 175102K->174974K(175104K)] 204787K->203220K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0266390 secs] [Times: user=0.20 sys=0.00, real=0.03 secs]
2023-05-24T16:59:49.303+0800: [Full GC (Ergonomics) [PSYoungGen: 29093K->28301K(58368K)] [ParOldGen: 174974K->174870K(175104K)] 204068K->203171K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0143471 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-05-24T16:59:49.318+0800: [Full GC (Ergonomics) [PSYoungGen: 29569K->28301K(58368K)] [ParOldGen: 174870K->174870K(175104K)] 204439K->203171K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0020768 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-24T16:59:49.320+0800: [Full GC (Ergonomics) [PSYoungGen: 29690K->29156K(58368K)] [ParOldGen: 174870K->174870K(175104K)] 204560K->204026K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0033312 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-24T16:59:49.323+0800: [Full GC (Ergonomics) [PSYoungGen: 29645K->29120K(58368K)] [ParOldGen: 174870K->174870K(175104K)] 204515K->203990K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0022323 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-24T16:59:49.326+0800: [Full GC (Ergonomics) [PSYoungGen: 29644K->29524K(58368K)] [ParOldGen: 174870K->174679K(175104K)] 204514K->204203K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0205500 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2023-05-24T16:59:49.347+0800: [Full GC (Ergonomics) [PSYoungGen: 29583K->29511K(58368K)] [ParOldGen: 174679K->174497K(175104K)] 204263K->204009K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0100086 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2023-05-24T16:59:49.357+0800: [Full GC (Ergonomics) [PSYoungGen: 29511K->29511K(58368K)] [ParOldGen: 174817K->174817K(175104K)] 204329K->204329K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0020574 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-24T16:59:49.359+0800: [Full GC (Allocation Failure) [PSYoungGen: 29511K->29511K(58368K)] [ParOldGen: 174817K->174798K(175104K)] 204329K->204310K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0333040 secs] [Times: user=0.27 sys=0.00, real=0.03 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at GCLogAnalysis.generateGarbage(GCLogAnalysis.java:49)
        at GCLogAnalysis.main(GCLogAnalysis.java:27)

可以看到每次回收，堆内存的释放量都很有限，知道最终一点内存也没有释放掉，就oom了。

2.2：Java8 1g 串行GC

$ D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx512m -Xms512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseSerialGC -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
2023-05-24T17:27:33.124+0800: [GC (Allocation Failure) 2023-05-24T17:27:33.124+0800: [DefNew: 139776K->17472K(157248K), 0.0210852 secs] 139776K->46760K(506816K), 
0.0211440 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
...
2023-05-24T17:27:33.895+0800: [GC (Allocation Failure) 2023-05-24T17:27:33.895+0800: [DefNew: 139776K->139776K(157248K), 0.0000138 secs]2023-05-24T17:27:33.895+0800: [Tenured: 346101K->349506K(349568K), 0.0542652 secs] 485877K->352348K(506816K), [Metaspace: 2679K->2679K(1056768K)], 0.0543181 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
2023-05-24T17:27:33.968+0800: [Full GC (Allocation Failure) 2023-05-24T17:27:33.968+0800: [Tenured: 349506K->349333K(349568K), 0.0550629 secs] 506618K->360695K(506816K), [Metaspace: 2679K->2679K(1056768K)], 0.0551013 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2023-05-24T17:27:34.043+0800: [Full GC (Allocation Failure) 2023-05-24T17:27:34.043+0800: [Tenured: 349333K->349390K(349568K), 0.0591635 secs] 506564K->349390K(506816K), [Metaspace: 2679K->2679K(1056768K)], 0.0592023 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
执行结束!共生成对象次数:10066
Heap
 def new generation   total 157248K, used 6218K [0x00000000e0000000, 0x00000000eaaa0000, 0x00000000eaaa0000)
  eden space 139776K,   4% used [0x00000000e0000000, 0x00000000e06128b0, 0x00000000e8880000)
  from space 17472K,   0% used [0x00000000e9990000, 0x00000000e9990000, 0x00000000eaaa0000)
  to   space 17472K,   0% used [0x00000000e8880000, 0x00000000e8880000, 0x00000000e9990000)
 tenured generation   total 349568K, used 349390K [0x00000000eaaa0000, 0x0000000100000000, 0x0000000100000000)
   the space 349568K,  99% used [0x00000000eaaa0000, 0x00000000fffd39f8, 0x00000000fffd3a00, 0x0000000100000000)
 Metaspace       used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

用的不多，放在这里。

2.3：Java8 cms

如下：

$ D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx1g -Xms1g -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
2023-05-25T09:57:31.273+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.273+0800: [ParNew: 279616K->34940K(314560K), 0.0159536 secs] 279616K->90419K(1013632K), 0.0160054 secs] [Times: user=0.05 sys=0.11, real=0.02 secs]
2023-05-25T09:57:31.326+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.326+0800: [ParNew: 314556K->34944K(314560K), 0.0224840 secs] 370035K->164503K(1013632K), 0.0225199 secs] [Times: user=0.19 sys=0.13, real=0.02 secs]
2023-05-25T09:57:31.383+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.383+0800: [ParNew: 314346K->34942K(314560K), 0.0472633 secs] 443906K->251967K(1013632K), 0.0473368 secs] [Times: user=0.42 sys=0.05, real=0.05 secs]
2023-05-25T09:57:31.461+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.461+0800: [ParNew: 314558K->34944K(314560K), 0.0445762 secs] 531583K->331056K(1013632K), 0.0446123 secs] [Times: user=0.45 sys=0.01, real=0.05 secs]
2023-05-25T09:57:31.539+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.539+0800: [ParNew: 314560K->34944K(314560K), 0.0463805 secs] 610672K->416507K(1013632K), 0.0464141 secs] [Times: user=0.41 sys=0.02, real=0.05 secs]
2023-05-25T09:57:31.587+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 381563K(699072K)] 422843K(1013632K), 0.0005295 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.588+0800: [CMS-concurrent-mark-start]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-preclean-start]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-abortable-preclean-start]
2023-05-25T09:57:31.619+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.619+0800: [ParNew: 314204K->34943K(314560K), 0.0481115 secs] 695767K->502801K(1013632K), 0.0481485 secs] [Times: user=0.45 sys=0.01, real=0.05 secs]
2023-05-25T09:57:31.701+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.701+0800: [ParNew: 314559K->34943K(314560K), 0.0432533 secs] 782417K->581570K(1013632K), 0.0432892 secs] [Times: user=0.45 sys=0.02, real=0.04 secs]
2023-05-25T09:57:31.776+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.776+0800: [ParNew: 314559K->34943K(314560K), 0.0380490 secs] 861186K->649099K(1013632K), 0.0380865 secs] [Times: user=0.47 sys=0.00, real=0.04 secs]
2023-05-25T09:57:31.846+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.847+0800: [ParNew: 314559K->314559K(314560K), 0.0000206 secs]2023-05-25T09:57:31.847+0800: [CMS2023-05-25T09:57:31.847+0800: [CMS-concurrent-abortable-preclean: 0.007/0.257 secs] [Times: user=1.50 sys=0.03, real=0.26 secs]
 (concurrent mode failure): 614155K->346210K(699072K), 0.0607158 secs] 928715K->346210K(1013632K), [Metaspace: 2679K->2679K(1056768K)], 0.0613162 secs] [Times: user=0.05 sys=0.02, real=0.06 secs]
2023-05-25T09:57:31.945+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.945+0800: [ParNew: 279616K->34942K(314560K), 0.0142289 secs] 625826K->432519K(1013632K), 0.0142609 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-05-25T09:57:31.959+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 397577K(699072K)] 432616K(1013632K), 0.0007559 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.960+0800: [CMS-concurrent-mark-start]
2023-05-25T09:57:31.961+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.961+0800: [CMS-concurrent-preclean-start]
2023-05-25T09:57:31.962+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.962+0800: [CMS-concurrent-abortable-preclean-start]
2023-05-25T09:57:31.995+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.995+0800: [ParNew: 314558K->34943K(314560K), 0.0195717 secs] 712135K->504639K(1013632K), 0.0196084 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-05-25T09:57:32.050+0800: [GC (Allocation Failure) 2023-05-25T09:57:32.050+0800: [ParNew: 314559K->34943K(314560K), 0.0201785 secs] 784255K->584424K(1013632K), 0.0202243 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-05-25T09:57:32.108+0800: [GC (Allocation Failure) 2023-05-25T09:57:32.108+0800: [ParNew: 314559K->34943K(314560K), 0.0258440 secs] 864040K->664022K(1013632K), 0.0258836 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
执行结束!共生成对象次数:13959
Heap
 par new generation   total 314560K, used 76092K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K,  14% used [0x00000000c0000000, 0x00000000c282f590, 0x00000000d1110000)
  from space 34944K,  99% used [0x00000000d1110000, 0x00000000d332fd30, 0x00000000d3330000)
  to   space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330000, 0x00000000d5550000)
 concurrent mark-sweep generation total 699072K, used 629079K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

最开始发生了5次young GC，接着发生了CMS GC，即Old GC，我们先来看第一个young GC：

2023-05-25T09:57:31.273+0800: [GC (Allocation Failure) 2023-05-25T09:57:31.273+0800: [ParNew: 279616K->34940K(314560K), 0.0159536 secs] 279616K->90419K(1013632K), 0.0160054 secs] [Times: user=0.05 sys=0.11, real=0.02 secs]
2023-05-25T09:57:31.273+0800:
    GC发生的时间
GC (Allocation Failure)：
    GC发生的原因
ParNew: 279616K->34940K(314560K):
    young GC使用的垃圾收集器是ParNew，一种serail垃圾收集器的并行版本，GC前内存占用量是279616K，GC后内存占用量是34940K，young内存占用量减少了279616K-34940K=244,676K
279616K->90419K(1013632K):
    整个堆内存GC前占用量是279616K，这里和young GC前内存占用量是一样的，这是因为所有的对象都是在young，old并没有，GC后内存占用量是90419K，即整个堆内存占用量减少了279616K-90419K=189,197K
0.0160054 secs:
    stw时间是16ms,速度非常快

5次young GC之后发生了CSM GC，即old GC，整个日志体现了CMS GC的6个阶段 如下：

// 初始标记，有stw，非常短，这是0.0005295 secs，即5ms
2023-05-25T09:57:31.587+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 381563K(699072K)] 422843K(1013632K), 0.0005295 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
// 并发标记开始
2023-05-25T09:57:31.588+0800: [CMS-concurrent-mark-start]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
// 并发预处理开始
2023-05-25T09:57:31.590+0800: [CMS-concurrent-preclean-start]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-05-25T09:57:31.590+0800: [CMS-concurrent-abortable-preclean-start]

不知为何我的测试输出了CMS-concurrent-abortable-preclean-start之后，就没有了最终标记，并发清除，并发重置三个阶段了。

此时内存1g，是触发了old GC的，我们增加到4g看下：

$ D:\\program_files\\many_version_jdk\\jdk1.8.0_202\\bin\\java -Xmx4g -Xms4g -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC -Dfile.encoding=UTF-8 GCLogAnalysis
正在执行...
2023-05-25T13:30:24.605+0800: [GC (Allocation Failure) 2023-05-25T13:30:24.605+0800: [ParNew: 681600K->85184K(766784K), 0.0437130 secs] 681600K->173484K(4109120K), 0.0437688 secs] [Times: user=0.22 sys=0.23, real=0.04 secs]
2023-05-25T13:30:24.741+0800: [GC (Allocation Failure) 2023-05-25T13:30:24.741+0800: [ParNew: 766784K->85182K(766784K), 0.0627374 secs] 855084K->316578K(4109120K), 0.0627742 secs] [Times: user=0.25 sys=0.30, real=0.06 secs]
2023-05-25T13:30:24.886+0800: [GC (Allocation Failure) 2023-05-25T13:30:24.886+0800: [ParNew: 766782K->85182K(766784K), 0.0858542 secs] 998178K->455697K(4109120K), 0.0858906 secs] [Times: user=0.72 sys=0.05, real=0.09 secs]
2023-05-25T13:30:25.058+0800: [GC (Allocation Failure) 2023-05-25T13:30:25.058+0800: [ParNew: 766782K->85184K(766784K), 0.0797974 secs] 1137297K->585914K(4109120K), 0.0799399 secs] [Times: user=0.74 sys=0.05, real=0.08 secs]
2023-05-25T13:30:25.219+0800: [GC (Allocation Failure) 2023-05-25T13:30:25.219+0800: [ParNew: 766784K->85183K(766784K), 0.0802810 secs] 1267514K->713221K(4109120K), 0.0803223 secs] [Times: user=0.67 sys=0.09, real=0.08 secs]
执行结束!共生成对象次数:12861
Heap
 par new generation   total 766784K, used 112578K [0x00000006c0000000, 0x00000006f4000000, 0x00000006f4000000)
  eden space 681600K,   4% used [0x00000006c0000000, 0x00000006c1ac0b00, 0x00000006e99a0000)
  from space 85184K,  99% used [0x00000006eecd0000, 0x00000006f3ffffa0, 0x00000006f4000000)
  to   space 85184K,   0% used [0x00000006e99a0000, 0x00000006e99a0000, 0x00000006eecd0000)
 concurrent mark-sweep generation total 3342336K, used 628038K [0x00000006f4000000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

只有young GC了，这此时一个正常运行状态，只有young GC，而没有old GC和FULL GC。

写在后面

参考文章列表

GC-对象进入老年代的条件 。

一次线上JVM Young GC调优，搞懂了这么多东西！ 。