GC日志解读解析

示例代码

package jvm.test1;

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;

/**
 * GC demo
 *
 * @author hyq
 * @version 1.0.0
 * @date 2023/10/22 10:20
 */
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;
    }
}

日志解读

运行后使用命令行执行命令：

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx1g -Xms1g jvm.test1.GCLogAnalysis

命令解读：

-XX:+PrintGCDetails：打印GC日志
-XX:+PrintGCDateStamps：日志中显示时间
-Xmx1g：配置最大堆内存
-Xms1g：配置初始堆内存

打印结果：

正在执行...
2023-10-22T10:42:44.653+0800: [GC (Allocation Failure) [PSYoungGen: 262144K->43515K(305664K)] 262144K->82468K(1005056K), 0.0106982 secs] [Times: user=0.02 sys=0.14, real=0.01 secs]
2023-10-22T10:42:44.696+0800: [GC (Allocation Failure) [PSYoungGen: 305659K->43512K(305664K)] 344612K->145302K(1005056K), 0.0129678 secs] [Times: user=0.02 sys=0.14, real=0.01 secs]
2023-10-22T10:42:44.738+0800: [GC (Allocation Failure) [PSYoungGen: 305656K->43519K(305664K)] 407446K->227564K(1005056K), 0.0161066 secs] [Times: user=0.06 sys=0.03, real=0.02 secs]
2023-10-22T10:42:44.783+0800: [GC (Allocation Failure) [PSYoungGen: 305663K->43504K(305664K)] 489708K->304311K(1005056K), 0.0149146 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T10:42:44.826+0800: [GC (Allocation Failure) [PSYoungGen: 305648K->43514K(305664K)] 566455K->383693K(1005056K), 0.0150872 secs] [Times: user=0.05 sys=0.11, real=0.02 secs]
2023-10-22T10:42:44.868+0800: [GC (Allocation Failure) [PSYoungGen: 305658K->43501K(160256K)] 645837K->456646K(859648K), 0.0150185 secs] [Times: user=0.01 sys=0.14, real=0.02 secs]
2023-10-22T10:42:44.897+0800: [GC (Allocation Failure) [PSYoungGen: 160237K->73764K(232960K)] 573382K->491756K(932352K), 0.0102376 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:44.924+0800: [GC (Allocation Failure) [PSYoungGen: 190500K->90530K(232960K)] 608492K->518925K(932352K), 0.0109217 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:44.948+0800: [GC (Allocation Failure) [PSYoungGen: 207219K->99617K(232960K)] 635614K->547816K(932352K), 0.0149653 secs] [Times: user=0.13 sys=0.02, real=0.02 secs]
2023-10-22T10:42:44.979+0800: [GC (Allocation Failure) [PSYoungGen: 216353K->72345K(232960K)] 664552K->576026K(932352K), 0.0149970 secs] [Times: user=0.13 sys=0.03, real=0.01 secs]
2023-10-22T10:42:45.007+0800: [GC (Allocation Failure) [PSYoungGen: 189081K->37448K(232960K)] 692762K->605738K(932352K), 0.0117881 secs] [Times: user=0.08 sys=0.05, real=0.01 secs]
2023-10-22T10:42:45.034+0800: [GC (Allocation Failure) [PSYoungGen: 154039K->40763K(232960K)] 722328K->641512K(932352K), 0.0089391 secs] [Times: user=0.03 sys=0.13, real=0.01 secs]
2023-10-22T10:42:45.044+0800: [Full GC (Ergonomics) [PSYoungGen: 40763K->0K(232960K)] [ParOldGen: 600748K->326930K(699392K)] 641512K->326930K(932352K), [Metaspace: 2593K->2593K(1056768K)], 0.0444688 secs] [Times: user=0.31 sys=0.00, real=0.05 secs]
2023-10-22T10:42:45.101+0800: [GC (Allocation Failure) [PSYoungGen: 116736K->38686K(232960K)] 443666K->365617K(932352K), 0.0066952 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.123+0800: [GC (Allocation Failure) [PSYoungGen: 155422K->37867K(232960K)] 482353K->400040K(932352K), 0.0090454 secs] [Times: user=0.13 sys=0.02, real=0.01 secs]
2023-10-22T10:42:45.145+0800: [GC (Allocation Failure) [PSYoungGen: 154603K->39876K(232960K)] 516776K->437097K(932352K), 0.0083256 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.164+0800: [GC (Allocation Failure) [PSYoungGen: 156612K->41100K(232960K)] 553833K->472285K(932352K), 0.0117009 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.191+0800: [GC (Allocation Failure) [PSYoungGen: 157836K->35637K(232960K)] 589021K->503674K(932352K), 0.0086286 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.213+0800: [GC (Allocation Failure) [PSYoungGen: 152373K->38837K(232960K)] 620410K->537995K(932352K), 0.0079149 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.237+0800: [GC (Allocation Failure) [PSYoungGen: 155573K->39375K(232960K)] 654731K->571803K(932352K), 0.0090923 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.260+0800: [GC (Allocation Failure) [PSYoungGen: 156111K->44983K(232960K)] 688539K->612688K(932352K), 0.0091386 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.282+0800: [GC (Allocation Failure) [PSYoungGen: 161719K->41464K(232960K)] 729424K->649423K(932352K), 0.0097807 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.305+0800: [GC (Allocation Failure) [PSYoungGen: 158200K->40720K(232960K)] 766159K->685670K(932352K), 0.0087884 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.316+0800: [Full GC (Ergonomics) [PSYoungGen: 40720K->0K(232960K)] [ParOldGen: 644949K->363234K(699392K)] 685670K->363234K(932352K), [Metaspace: 2593K->2593K(1056768K)], 0.0413510 secs] [Times: user=0.45 sys=0.00, real=0.04 secs]
2023-10-22T10:42:45.370+0800: [GC (Allocation Failure) [PSYoungGen: 116492K->39984K(232960K)] 479727K->403219K(932352K), 0.0049756 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T10:42:45.389+0800: [GC (Allocation Failure) [PSYoungGen: 156720K->38871K(232960K)] 519955K->439875K(932352K), 0.0077945 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.410+0800: [GC (Allocation Failure) [PSYoungGen: 155607K->34324K(232960K)] 556611K->469402K(932352K), 0.0085923 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.431+0800: [GC (Allocation Failure) [PSYoungGen: 151060K->36936K(234496K)] 586138K->501398K(933888K), 0.0077600 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.452+0800: [GC (Allocation Failure) [PSYoungGen: 155208K->38983K(232960K)] 619670K->537946K(932352K), 0.0080312 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.474+0800: [GC (Allocation Failure) [PSYoungGen: 157255K->36818K(242688K)] 656218K->569737K(942080K), 0.0086857 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.498+0800: [GC (Allocation Failure) [PSYoungGen: 169426K->43702K(239104K)] 702345K->608432K(938496K), 0.0084237 secs] [Times: user=0.09 sys=0.00, real=0.01 secs]
2023-10-22T10:42:45.521+0800: [GC (Allocation Failure) [PSYoungGen: 176310K->45593K(252928K)] 741040K->648530K(952320K), 0.0094425 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
执行结束!共生成对象次数:17065
Heap
 PSYoungGen      total 252928K, used 111937K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 151552K, 43% used [0x00000000eab00000,0x00000000eebca0f8,0x00000000f3f00000)
  from space 101376K, 44% used [0x00000000f9d00000,0x00000000fc9864f0,0x0000000100000000)
  to   space 96256K, 0% used [0x00000000f3f00000,0x00000000f3f00000,0x00000000f9d00000)
 ParOldGen       total 699392K, used 602937K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
  object space 699392K, 86% used [0x00000000c0000000,0x00000000e4cce450,0x00000000eab00000)
 Metaspace       used 2600K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 279K, capacity 386K, committed 512K, reserved 1048576K

日志解读，先看开头一句：

2023-10-22T10:42:44.653+0800: [GC (Allocation Failure) [PSYoungGen: 262144K->43515K(305664K)] 262144K->82468K(1005056K), 0.0106982 secs] [Times: user=0.02 sys=0.14, real=0.01 secs]

分为两部分：

[GC (Allocation Failure) [PSYoungGen: 262144K->43515K(305664K)] 262144K->82468K(1005056K), 0.0106982 secs]：GC执行情况
[Times: user=0.02 sys=0.14, real=0.01 secs]：CPU执行情况。

第一部分解读：

2023-10-22T10:42:44.653+0800：时间戳
GC (Allocation Failure)：内存分配失败，所以进行一次GC操作
[PSYoungGen: 262144K->43515K(305664K)]：YoungGC操作，GC前的大小为 262144K（256M），GC后的大小为43515K（42.49M），说明通过这次GC，Young区压缩了 (256-42.49=213.51M) 的容量。后面括号里的 (305664K) 表示Young区的最大容量（298.5M）
262144K->82468K(1005056K)：整个堆内存在GC过后的情况，整个堆内存从原来的262144K（256M）压缩到了82468K（80.53M），堆内存的最大容量就是(1005056K)差不多1g左右的容量。
0.0106982 secs：表示GC暂停（STW）的时间，单位秒。可以看到大概是10ms左右。

在分析中可以发现，在GC之后，整个堆内存的大小（80.53M）要大于Young区的大小（42.49M）。所以可以得出，中间整个差值，其实就是进入了Old区的容量，也就是有 (80.53-42.49=38.04M) 容量大小的数据进入了Old区。

说明这一次的YoungGC有38M的数据从Young区晋升到了Old区。

问题1：

在GC日志中，为什么在进行多次GC之后，Young区的最大容量在变化，且越变越小？整个堆内存的最大容量同理问题？

答：

在Java8中，默认情况下自适应参数是打开的（-XX:+UseAdaptiveSizePolicy），也就是说默认情况下JVM会根据自己的一些算法去动态的调整各种容量的大小，以及调整一些其他的相关参数。比如晋升阈值，我们默认参数是在经过15次YoungGC还没有被回收掉的情况下，再晋升到老年代。但是在自适应参数打开的情况下，不一定是15次。可能没经过几次YoungGC就直接晋升到Old区了。

所以在日志中也可以看到，在自适应参数的影响下，每次进行YoungGC的时间差别也是挺大的，也就是GC暂停时间其实是不可控的。

看完了第一句，继续往下看。

在经过12次的YoungGC之后，进行了一次FullGC，日志如下：

2023-10-22T10:42:45.044+0800: [Full GC (Ergonomics) [PSYoungGen: 40763K->0K(232960K)] [ParOldGen: 600748K->326930K(699392K)] 641512K->326930K(932352K), [Metaspace: 2593K->2593K(1056768K)], 0.0444688 secs] [Times: user=0.31 sys=0.00, real=0.05 secs]

经过上面的分析，这个日志就很好解读了：

Full GC (Ergonomics) ：进行FullGC。在执行FullGC操作的时候，会同时进行Young区的GC和Old区的GC。
[PSYoungGen: 40763K->0K(232960K)]：FullGC中的YoungGC直接把Young区的内存清空为0。
[ParOldGen: 600748K->326930K(699392K)]：OldGC操作，从原来的600748K（586.67M）压缩到326930K（319.27M），整个Old区大小为699392K（683M）。
[Metaspace: 2593K->2593K(1056768K)]：元数据区大小不变，GC之后并没有发生变化。因为元数据区不归GC管理。
0.0444688 secs：FullGC执行的时间（STW）是44ms，可以发现与YoungGC相比，时间长了很多。

问题2：

为什么进行FullGC时会把所有的Young区空间清空？

学会GC日志解读之后，可以使用不同的参数多次尝试查看内存变化情况。比如：

将原来的内存从1g改为512m：

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx512m -Xms512m jvm.test1.GCLogAnalysis

可以看到打印的GC日志中，FullGC在后期变的十分频繁：

正在执行...
2023-10-22T11:34:33.616+0800: [GC (Allocation Failure) [PSYoungGen: 131584K->21503K(153088K)] 131584K->44141K(502784K), 0.0061744 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.640+0800: [GC (Allocation Failure) [PSYoungGen: 153087K->21502K(153088K)] 175725K->79042K(502784K), 0.0080500 secs] [Times: user=0.03 sys=0.13, real=0.01 secs]
2023-10-22T11:34:33.663+0800: [GC (Allocation Failure) [PSYoungGen: 153086K->21501K(153088K)] 210626K->120657K(502784K), 0.0080029 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.685+0800: [GC (Allocation Failure) [PSYoungGen: 153085K->21498K(153088K)] 252241K->167313K(502784K), 0.0089167 secs] [Times: user=0.05 sys=0.11, real=0.01 secs]
2023-10-22T11:34:33.708+0800: [GC (Allocation Failure) [PSYoungGen: 153082K->21494K(153088K)] 298897K->209986K(502784K), 0.0091340 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.734+0800: [GC (Allocation Failure) [PSYoungGen: 152938K->21495K(80384K)] 341430K->248955K(430080K), 0.0087255 secs] [Times: user=0.08 sys=0.08, real=0.01 secs]
2023-10-22T11:34:33.749+0800: [GC (Allocation Failure) [PSYoungGen: 79789K->39171K(116736K)] 307248K->270763K(466432K), 0.0073627 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.764+0800: [GC (Allocation Failure) [PSYoungGen: 98051K->55773K(116736K)] 329643K->292926K(466432K), 0.0084902 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.780+0800: [GC (Allocation Failure) [PSYoungGen: 114653K->57842K(116736K)] 351806K->309930K(466432K), 0.0086728 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.796+0800: [GC (Allocation Failure) [PSYoungGen: 116516K->37331K(116736K)] 368603K->323761K(466432K), 0.0099382 secs] [Times: user=0.11 sys=0.03, real=0.01 secs]
2023-10-22T11:34:33.814+0800: [GC (Allocation Failure) [PSYoungGen: 95952K->22389K(116736K)] 382382K->343104K(466432K), 0.0075411 secs] [Times: user=0.03 sys=0.13, real=0.01 secs]
2023-10-22T11:34:33.822+0800: [Full GC (Ergonomics) [PSYoungGen: 22389K->0K(116736K)] [ParOldGen: 320715K->244900K(349696K)] 343104K->244900K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0313838 secs] [Times: user=0.25 sys=0.00, real=0.03 secs]
2023-10-22T11:34:33.861+0800: [GC (Allocation Failure) [PSYoungGen: 58880K->22539K(116736K)] 303780K->267439K(466432K), 0.0050582 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
2023-10-22T11:34:33.873+0800: [GC (Allocation Failure) [PSYoungGen: 80980K->22263K(116736K)] 325881K->287822K(466432K), 0.0077184 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.889+0800: [GC (Allocation Failure) [PSYoungGen: 81143K->23257K(116736K)] 346702K->309394K(466432K), 0.0072492 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.903+0800: [GC (Allocation Failure) [PSYoungGen: 82137K->23078K(116736K)] 368274K->331755K(466432K), 0.0076308 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:33.913+0800: [Full GC (Ergonomics) [PSYoungGen: 23078K->0K(116736K)] [ParOldGen: 308677K->272030K(349696K)] 331755K->272030K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0300297 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
2023-10-22T11:34:33.950+0800: [GC (Allocation Failure) [PSYoungGen: 58458K->17952K(116736K)] 330489K->289983K(466432K), 0.0025355 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:33.958+0800: [GC (Allocation Failure) [PSYoungGen: 76832K->17171K(116736K)] 348863K->306219K(466432K), 0.0037998 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:33.968+0800: [GC (Allocation Failure) [PSYoungGen: 75922K->21118K(116736K)] 364970K->326096K(466432K), 0.0052516 secs] [Times: user=0.14 sys=0.00, real=0.00 secs]
2023-10-22T11:34:33.982+0800: [GC (Allocation Failure) [PSYoungGen: 79954K->23322K(116736K)] 384933K->348975K(466432K), 0.0047665 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:33.989+0800: [Full GC (Ergonomics) [PSYoungGen: 23322K->0K(116736K)] [ParOldGen: 325652K->298374K(349696K)] 348975K->298374K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0320178 secs] [Times: user=0.25 sys=0.01, real=0.03 secs]
2023-10-22T11:34:34.027+0800: [GC (Allocation Failure) [PSYoungGen: 58355K->21448K(116736K)] 356730K->319823K(466432K), 0.0028027 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:34.037+0800: [GC (Allocation Failure) [PSYoungGen: 80228K->19617K(116736K)] 378603K->338270K(466432K), 0.0043241 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:34:34.042+0800: [Full GC (Ergonomics) [PSYoungGen: 19617K->0K(116736K)] [ParOldGen: 318653K->306529K(349696K)] 338270K->306529K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0324151 secs] [Times: user=0.23 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.083+0800: [GC (Allocation Failure) [PSYoungGen: 58880K->22083K(116736K)] 365409K->328612K(466432K), 0.0028208 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:34.092+0800: [GC (Allocation Failure) [PSYoungGen: 80963K->22616K(116736K)] 387492K->348625K(466432K), 0.0065594 secs] [Times: user=0.13 sys=0.02, real=0.01 secs]
2023-10-22T11:34:34.099+0800: [Full GC (Ergonomics) [PSYoungGen: 22616K->0K(116736K)] [ParOldGen: 326008K->309183K(349696K)] 348625K->309183K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0319947 secs] [Times: user=0.28 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.140+0800: [GC (Allocation Failure) [PSYoungGen: 58797K->20792K(116736K)] 367981K->329975K(466432K), 0.0042225 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:34.151+0800: [GC (Allocation Failure) [PSYoungGen: 79633K->19463K(116736K)] 388817K->348867K(466432K), 0.0045630 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:34:34.156+0800: [Full GC (Ergonomics) [PSYoungGen: 19463K->0K(116736K)] [ParOldGen: 329403K->316744K(349696K)] 348867K->316744K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0330345 secs] [Times: user=0.27 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.196+0800: [Full GC (Ergonomics) [PSYoungGen: 58787K->0K(116736K)] [ParOldGen: 316744K->321587K(349696K)] 375532K->321587K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0337917 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.237+0800: [Full GC (Ergonomics) [PSYoungGen: 58775K->0K(116736K)] [ParOldGen: 321587K->322985K(349696K)] 380362K->322985K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0333286 secs] [Times: user=0.23 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.278+0800: [Full GC (Ergonomics) [PSYoungGen: 58841K->0K(116736K)] [ParOldGen: 322985K->324126K(349696K)] 381827K->324126K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0330376 secs] [Times: user=0.22 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.318+0800: [Full GC (Ergonomics) [PSYoungGen: 58880K->0K(116736K)] [ParOldGen: 324126K->328109K(349696K)] 383006K->328109K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0332028 secs] [Times: user=0.22 sys=0.01, real=0.03 secs]
2023-10-22T11:34:34.358+0800: [Full GC (Ergonomics) [PSYoungGen: 58686K->0K(116736K)] [ParOldGen: 328109K->329865K(349696K)] 386795K->329865K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0321959 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.399+0800: [Full GC (Ergonomics) [PSYoungGen: 58880K->0K(116736K)] [ParOldGen: 329865K->329187K(349696K)] 388745K->329187K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0337444 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.439+0800: [Full GC (Ergonomics) [PSYoungGen: 58880K->0K(116736K)] [ParOldGen: 329187K->334196K(349696K)] 388067K->334196K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0313719 secs] [Times: user=0.25 sys=0.06, real=0.03 secs]
2023-10-22T11:34:34.479+0800: [Full GC (Ergonomics) [PSYoungGen: 58800K->0K(116736K)] [ParOldGen: 334196K->336789K(349696K)] 392997K->336789K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0338116 secs] [Times: user=0.28 sys=0.00, real=0.03 secs]
2023-10-22T11:34:34.519+0800: [Full GC (Ergonomics) [PSYoungGen: 58880K->0K(116736K)] [ParOldGen: 336789K->340671K(349696K)] 395669K->340671K(466432K), [Metaspace: 2593K->2593K(1056768K)], 0.0347728 secs] [Times: user=0.23 sys=0.00, real=0.04 secs]
执行结束!共生成对象次数:9224
Heap
 PSYoungGen      total 116736K, used 21868K [0x00000000f5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 58880K, 37% used [0x00000000f5580000,0x00000000f6adb088,0x00000000f8f00000)
  from space 57856K, 0% used [0x00000000f8f00000,0x00000000f8f00000,0x00000000fc780000)
  to   space 57856K, 0% used [0x00000000fc780000,0x00000000fc780000,0x0000000100000000)
 ParOldGen       total 349696K, used 340671K [0x00000000e0000000, 0x00000000f5580000, 0x00000000f5580000)
  object space 349696K, 97% used [0x00000000e0000000,0x00000000f4cafd70,0x00000000f5580000)
 Metaspace       used 2600K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 279K, capacity 386K, committed 512K, reserved 1048576K

问题3：

在后期进行多次的FullGC后，为什么每次的FullGC，Old区的最大内存数不变，但是已使用内存在不断增大？是因为Old区已经没有可以可清除的数据？还是从Young区晋升数据大于Old区可清除数据？

问题4：

后期的几次FullGC为什么都固定在58800K这个数值？明明没有到达Young区的最大容量？

将512m改为256m

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx256m -Xms256m jvm.test1.GCLogAnalysis

可以看到打印出来的GC日志，在发生了十分频繁的FullGC之后，产生了OOM错误：

正在执行...
2023-10-22T11:47:00.332+0800: [GC (Allocation Failure) [PSYoungGen: 65536K->10729K(76288K)] 65536K->25038K(251392K), 0.0047135 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.347+0800: [GC (Allocation Failure) [PSYoungGen: 76265K->10747K(76288K)] 90574K->48822K(251392K), 0.0055067 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.362+0800: [GC (Allocation Failure) [PSYoungGen: 76283K->10743K(76288K)] 114358K->68707K(251392K), 0.0049960 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.375+0800: [GC (Allocation Failure) [PSYoungGen: 76171K->10745K(76288K)] 134136K->93523K(251392K), 0.0055150 secs] [Times: user=0.05 sys=0.11, real=0.01 secs]
2023-10-22T11:47:00.388+0800: [GC (Allocation Failure) [PSYoungGen: 76281K->10734K(76288K)] 159059K->115450K(251392K), 0.0054413 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]
2023-10-22T11:47:00.403+0800: [GC (Allocation Failure) [PSYoungGen: 76270K->10750K(40448K)] 180986K->137946K(215552K), 0.0048566 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:00.412+0800: [GC (Allocation Failure) [PSYoungGen: 40428K->19084K(58368K)] 167624K->147959K(233472K), 0.0035682 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:00.420+0800: [GC (Allocation Failure) [PSYoungGen: 48759K->24449K(58368K)] 177634K->157517K(233472K), 0.0045128 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:00.428+0800: [GC (Allocation Failure) [PSYoungGen: 54145K->28223K(58368K)] 187213K->165952K(233472K), 0.0078926 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.440+0800: [GC (Allocation Failure) [PSYoungGen: 57706K->19222K(58368K)] 195435K->176371K(233472K), 0.0048508 secs] [Times: user=0.11 sys=0.05, real=0.00 secs]
2023-10-22T11:47:00.445+0800: [Full GC (Ergonomics) [PSYoungGen: 19222K->0K(58368K)] [ParOldGen: 157149K->143135K(175104K)] 176371K->143135K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0203569 secs] [Times: user=0.14 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.471+0800: [GC (Allocation Failure) [PSYoungGen: 29641K->6709K(58368K)] 172777K->149845K(233472K), 0.0016497 secs] [Times: user=0.16 sys=0.00, real=0.00 secs]
2023-10-22T11:47:00.477+0800: [GC (Allocation Failure) [PSYoungGen: 36405K->12196K(58368K)] 179541K->161953K(233472K), 0.0062448 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.485+0800: [Full GC (Ergonomics) [PSYoungGen: 12196K->0K(58368K)] [ParOldGen: 149757K->154471K(175104K)] 161953K->154471K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0179045 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.506+0800: [Full GC (Ergonomics) [PSYoungGen: 29089K->0K(58368K)] [ParOldGen: 154471K->160311K(175104K)] 183561K->160311K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0187762 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.530+0800: [Full GC (Ergonomics) [PSYoungGen: 29470K->0K(58368K)] [ParOldGen: 160311K->163071K(175104K)] 189781K->163071K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0169938 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.552+0800: [Full GC (Ergonomics) [PSYoungGen: 29681K->0K(58368K)] [ParOldGen: 163071K->168324K(175104K)] 192753K->168324K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0195437 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.577+0800: [Full GC (Ergonomics) [PSYoungGen: 29119K->0K(58368K)] [ParOldGen: 168324K->172516K(175104K)] 197443K->172516K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0191723 secs] [Times: user=0.16 sys=0.02, real=0.02 secs]
2023-10-22T11:47:00.602+0800: [Full GC (Ergonomics) [PSYoungGen: 29535K->2988K(58368K)] [ParOldGen: 172516K->174908K(175104K)] 202052K->177897K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0187837 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.626+0800: [Full GC (Ergonomics) [PSYoungGen: 29598K->9122K(58368K)] [ParOldGen: 174908K->175087K(175104K)] 204506K->184209K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0194607 secs] [Times: user=0.28 sys=0.01, real=0.02 secs]
2023-10-22T11:47:00.650+0800: [Full GC (Ergonomics) [PSYoungGen: 29463K->12266K(58368K)] [ParOldGen: 175087K->174339K(175104K)] 204550K->186605K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0186207 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.672+0800: [Full GC (Ergonomics) [PSYoungGen: 29624K->15924K(58368K)] [ParOldGen: 174339K->174968K(175104K)] 203963K->190892K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0173792 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.694+0800: [Full GC (Ergonomics) [PSYoungGen: 29554K->15911K(58368K)] [ParOldGen: 174968K->174853K(175104K)] 204523K->190765K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0185949 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.715+0800: [Full GC (Ergonomics) [PSYoungGen: 29478K->16906K(58368K)] [ParOldGen: 174853K->175012K(175104K)] 204331K->191919K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0189335 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.740+0800: [Full GC (Ergonomics) [PSYoungGen: 29696K->17039K(58368K)] [ParOldGen: 175012K->174985K(175104K)] 204708K->192024K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0183179 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.760+0800: [Full GC (Ergonomics) [PSYoungGen: 29696K->20736K(58368K)] [ParOldGen: 174985K->174778K(175104K)] 204681K->195515K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0192507 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.781+0800: [Full GC (Ergonomics) [PSYoungGen: 29112K->23962K(58368K)] [ParOldGen: 174778K->174845K(175104K)] 203891K->198807K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0145952 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.797+0800: [Full GC (Ergonomics) [PSYoungGen: 29608K->26705K(58368K)] [ParOldGen: 174845K->174724K(175104K)] 204453K->201429K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0197027 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.818+0800: [Full GC (Ergonomics) [PSYoungGen: 29514K->26644K(58368K)] [ParOldGen: 174724K->175082K(175104K)] 204238K->201727K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0239572 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
2023-10-22T11:47:00.845+0800: [Full GC (Ergonomics) [PSYoungGen: 29194K->28048K(58368K)] [ParOldGen: 175082K->174993K(175104K)] 204276K->203041K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0273258 secs] [Times: user=0.01 sys=0.00, real=0.03 secs]
2023-10-22T11:47:00.874+0800: [Full GC (Ergonomics) [PSYoungGen: 29325K->28364K(58368K)] [ParOldGen: 174993K->174993K(175104K)] 204319K->203357K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0020791 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:00.877+0800: [Full GC (Ergonomics) [PSYoungGen: 29640K->28551K(58368K)] [ParOldGen: 174993K->174662K(175104K)] 204633K->203214K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0282698 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
2023-10-22T11:47:00.907+0800: [Full GC (Ergonomics) [PSYoungGen: 29617K->28908K(58368K)] [ParOldGen: 174662K->174539K(175104K)] 204280K->203448K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0154353 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
2023-10-22T11:47:00.923+0800: [Full GC (Ergonomics) [PSYoungGen: 29500K->28525K(58368K)] [ParOldGen: 174539K->175050K(175104K)] 204040K->203576K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0286271 secs] [Times: user=0.23 sys=0.00, real=0.03 secs]
2023-10-22T11:47:00.954+0800: [Full GC (Ergonomics) [PSYoungGen: 29635K->28734K(58368K)] [ParOldGen: 175050K->174818K(175104K)] 204685K->203553K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0305824 secs] [Times: user=0.17 sys=0.00, real=0.03 secs]
2023-10-22T11:47:00.986+0800: [Full GC (Ergonomics) [PSYoungGen: 29560K->28989K(58368K)] [ParOldGen: 174818K->174754K(175104K)] 204378K->203744K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0126782 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:47:01.002+0800: [Full GC (Ergonomics) [PSYoungGen: 29689K->29076K(58368K)] [ParOldGen: 174754K->174724K(175104K)] 204444K->203801K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0256921 secs] [Times: user=0.01 sys=0.00, real=0.03 secs]
2023-10-22T11:47:01.032+0800: [Full GC (Ergonomics) [PSYoungGen: 29432K->29140K(58368K)] [ParOldGen: 174724K->174724K(175104K)] 204157K->203865K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0024545 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2023-10-22T11:47:01.036+0800: [Full GC (Ergonomics) [PSYoungGen: 29619K->29140K(58368K)] [ParOldGen: 174724K->174724K(175104K)] 204344K->203865K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0022098 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:01.039+0800: [Full GC (Ergonomics) [PSYoungGen: 29590K->29535K(58368K)] [ParOldGen: 174724K->174724K(175104K)] 204314K->204260K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0021245 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:01.042+0800: [Full GC (Ergonomics) [PSYoungGen: 29535K->29535K(58368K)] [ParOldGen: 174952K->174724K(175104K)] 204487K->204260K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0030772 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T11:47:01.046+0800: [Full GC (Allocation Failure) [PSYoungGen: 29535K->29535K(58368K)] [ParOldGen: 174724K->174694K(175104K)] 204260K->204229K(233472K), [Metaspace: 2593K->2593K(1056768K)], 0.0281814 secs] [Times: user=0.05 sys=0.00, real=0.03 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at jvm.test1.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:54)
        at jvm.test1.GCLogAnalysis.main(GCLogAnalysis.java:31)
Heap
 PSYoungGen      total 58368K, used 29696K [0x00000000fab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 29696K, 100% used [0x00000000fab00000,0x00000000fc800000,0x00000000fc800000)
  from space 28672K, 0% used [0x00000000fe400000,0x00000000fe400000,0x0000000100000000)
  to   space 28672K, 0% used [0x00000000fc800000,0x00000000fc800000,0x00000000fe400000)
 ParOldGen       total 175104K, used 174694K [0x00000000f0000000, 0x00000000fab00000, 0x00000000fab00000)
  object space 175104K, 99% used [0x00000000f0000000,0x00000000faa998f0,0x00000000fab00000)
 Metaspace       used 2624K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 282K, capacity 386K, committed 512K, reserved 1048576K

问题5：

通过观察可知，打印出的最大堆内存总是少于设置的最大堆内存数，这是为什么？

使用串行垃圾回收器

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx1g -Xms1g -XX:+UseSerialGC jvm.test1.GCLogAnalysis

打印的GC日志：

正在执行...
2023-10-22T11:54:52.030+0800: [GC (Allocation Failure) [DefNew: 279616K->34943K(314560K), 0.0379112 secs] 279616K->85749K(1013632K), 0.0383783 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
2023-10-22T11:54:52.103+0800: [GC (Allocation Failure) [DefNew: 314559K->34944K(314560K), 0.0467975 secs] 365365K->157108K(1013632K), 0.0472393 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
2023-10-22T11:54:52.182+0800: [GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.0372716 secs] 436724K->235717K(1013632K), 0.0376221 secs] [Times: user=0.00 sys=0.03, real=0.04 secs]
2023-10-22T11:54:52.248+0800: [GC (Allocation Failure) [DefNew: 314559K->34943K(314560K), 0.0397251 secs] 515333K->316217K(1013632K), 0.0403220 secs] [Times: user=0.03 sys=0.02, real=0.04 secs]
2023-10-22T11:54:52.320+0800: [GC (Allocation Failure) [DefNew: 314559K->34944K(314560K), 0.0370517 secs] 595833K->395057K(1013632K), 0.0373117 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]
2023-10-22T11:54:52.386+0800: [GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.0391055 secs] 674673K->477193K(1013632K), 0.0393680 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]
2023-10-22T11:54:52.455+0800: [GC (Allocation Failure) [DefNew: 314559K->34943K(314560K), 0.0379827 secs] 756809K->553364K(1013632K), 0.0389063 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
2023-10-22T11:54:52.522+0800: [GC (Allocation Failure) [DefNew: 313814K->34943K(314560K), 0.0499850 secs] 832235K->645249K(1013632K), 0.0519180 secs] [Times: user=0.02 sys=0.03, real=0.05 secs]
2023-10-22T11:54:52.603+0800: [GC (Allocation Failure) [DefNew: 314559K->314559K(314560K), 0.0005778 secs][Tenured: 610305K->374174K(699072K), 0.0410102 secs] 924865K->374174K(1013632K), [Metaspace: 2591K->2591K(1056768K)], 0.0422865 secs] [Times: user=0.05 sys=0.00, real=0.04 secs]
2023-10-22T11:54:52.674+0800: [GC (Allocation Failure) [DefNew: 279616K->34943K(314560K), 0.0102163 secs] 653790K->460214K(1013632K), 0.0106525 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2023-10-22T11:54:52.713+0800: [GC (Allocation Failure) [DefNew: 314559K->34943K(314560K), 0.0129679 secs] 739830K->534771K(1013632K), 0.0133039 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2023-10-22T11:54:52.754+0800: [GC (Allocation Failure) [DefNew: 314559K->34943K(314560K), 0.0121331 secs] 814387K->604041K(1013632K), 0.0123933 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2023-10-22T11:54:52.794+0800: [GC (Allocation Failure) [DefNew: 314559K->34943K(314560K), 0.0255837 secs] 883657K->680082K(1013632K), 0.0259624 secs] [Times: user=0.01 sys=0.02, real=0.03 secs]
2023-10-22T11:54:52.850+0800: [GC (Allocation Failure) [DefNew: 314559K->314559K(314560K), 0.0002745 secs][Tenured: 645139K->388330K(699072K), 0.0397241 secs] 959698K->388330K(1013632K), [Metaspace: 2593K->2593K(1056768K)], 0.0413796 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]
执行结束!共生成对象次数:15560
Heap
 def new generation   total 314560K, used 170776K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K,  61% used [0x00000000c0000000, 0x00000000ca6c61e0, 0x00000000d1110000)
  from space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
  to   space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330000, 0x00000000d5550000)
 tenured generation   total 699072K, used 388330K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
   the space 699072K,  55% used [0x00000000d5550000, 0x00000000ed08ab18, 0x00000000ed08ac00, 0x0000000100000000)
 Metaspace       used 2600K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 279K, capacity 386K, committed 512K, reserved 1048576K

因为是串行执行，所以YoungGC(DefNew)的垃圾回收时间与FullGC(Tenured)的垃圾回收时间差不了多少。

【额外】

如果JVM参数没有加上 -Xms1g 初始堆内存设置时，通过打印的日志会发现FullGC的次数变多。

原因是因为没有手动配置或者说没有配置的与 -Xmx 的值保持一致时，堆内存容量就没有到我们可能运用的最大值，那么一旦Old区满了就会产生FullGC，同时JVM会去申请一部分内存扩大空间，下次再次产生FullGC时再次去申请扩大，直到达到 -Xmx 最大容量值。

所以堆内存设置的大小有蓄水池的作用，设置成一样的也是为了防止GC抖动（因为内存不够而导致的频繁FullGC）。

最小配置肯定是要满足程序运行的大小，之后堆内存设置越大，GC的频率就越低，但是STW的时间就会相对变长。

使用CMS

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx1g -Xms1g -XX:+UseConcMarkSweepGC jvm.test1.GCLogAnalysis

GC日志：

正在执行...
2023-10-22T13:32:37.505+0800: [GC (Allocation Failure) [ParNew: 279616K->34942K(314560K), 0.0148922 secs] 279616K->80878K(1013632K), 0.0151922 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T13:32:37.554+0800: [GC (Allocation Failure) [ParNew: 314558K->34944K(314560K), 0.0192727 secs] 360494K->155158K(1013632K), 0.0201451 secs] [Times: user=0.06 sys=0.09, real=0.02 secs]
2023-10-22T13:32:37.608+0800: [GC (Allocation Failure) [ParNew: 314560K->34944K(314560K), 0.0386982 secs] 434774K->227634K(1013632K), 0.0389713 secs] [Times: user=0.44 sys=0.03, real=0.04 secs]
2023-10-22T13:32:37.676+0800: [GC (Allocation Failure) [ParNew: 314560K->34944K(314560K), 0.0418323 secs] 507250K->303351K(1013632K), 0.0421403 secs] [Times: user=0.31 sys=0.00, real=0.04 secs]
2023-10-22T13:32:37.748+0800: [GC (Allocation Failure) [ParNew: 314560K->34943K(314560K), 0.0448737 secs] 582967K->385104K(1013632K), 0.0454318 secs] [Times: user=0.44 sys=0.03, real=0.05 secs]
2023-10-22T13:32:37.795+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 350160K(699072K)] 391368K(1013632K), 0.0004048 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.796+0800: [CMS-concurrent-mark-start]
2023-10-22T13:32:37.799+0800: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.799+0800: [CMS-concurrent-preclean-start]
2023-10-22T13:32:37.801+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.801+0800: [CMS-concurrent-abortable-preclean-start]
2023-10-22T13:32:37.825+0800: [GC (Allocation Failure) [ParNew: 314559K->34944K(314560K), 0.0429650 secs] 664720K->467336K(1013632K), 0.0432853 secs] [Times: user=0.41 sys=0.06, real=0.04 secs]
2023-10-22T13:32:37.900+0800: [GC (Allocation Failure) [ParNew: 314560K->34943K(314560K), 0.0416909 secs] 746952K->542280K(1013632K), 0.0418688 secs] [Times: user=0.47 sys=0.00, real=0.04 secs]
2023-10-22T13:32:37.970+0800: [GC (Allocation Failure) [ParNew: 314559K->34943K(314560K), 0.0442964 secs] 821896K->623133K(1013632K), 0.0447649 secs] [Times: user=0.39 sys=0.08, real=0.05 secs]
2023-10-22T13:32:38.043+0800: [GC (Allocation Failure) [ParNew: 314559K->34943K(314560K), 0.0455547 secs] 902749K->707000K(1013632K), 0.0457322 secs] [Times: user=0.44 sys=0.03, real=0.05 secs]
2023-10-22T13:32:38.089+0800: [CMS-concurrent-abortable-preclean: 0.005/0.288 secs] [Times: user=1.80 sys=0.17, real=0.29 secs]
2023-10-22T13:32:38.090+0800: [GC (CMS Final Remark) [YG occupancy: 46618 K (314560 K)][Rescan (parallel) , 0.0003969 secs][weak refs processing, 0.0000571 secs][class unloading, 0.0002844 secs][scrub symbol table, 0.0002994 secs][scrub string table, 0.0002186 secs][1 CMS-remark: 672056K(699072K)] 718675K(1013632K), 0.0023804 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.094+0800: [CMS-concurrent-sweep-start]
2023-10-22T13:32:38.095+0800: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.096+0800: [CMS-concurrent-reset-start]
2023-10-22T13:32:38.098+0800: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.122+0800: [GC (Allocation Failure) [ParNew: 314559K->34943K(314560K), 0.0151640 secs] 871232K->676053K(1013632K), 0.0153384 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T13:32:38.137+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 641109K(699072K)] 682050K(1013632K), 0.0004848 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.138+0800: [CMS-concurrent-mark-start]
2023-10-22T13:32:38.140+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.143+0800: [CMS-concurrent-preclean-start]
2023-10-22T13:32:38.145+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.145+0800: [CMS-concurrent-abortable-preclean-start]
2023-10-22T13:32:38.148+0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.149+0800: [GC (CMS Final Remark) [YG occupancy: 129087 K (314560 K)][Rescan (parallel) , 0.0005396 secs][weak refs processing, 0.0000926 secs][class unloading, 0.0002457 secs][scrub symbol table, 0.0002998 secs][scrub string table, 0.0002303 secs][1 CMS-remark: 641109K(699072K)] 770197K(1013632K), 0.0021516 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.154+0800: [CMS-concurrent-sweep-start]
2023-10-22T13:32:38.157+0800: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.160+0800: [CMS-concurrent-reset-start]
2023-10-22T13:32:38.161+0800: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.176+0800: [GC (Allocation Failure) [ParNew: 314559K->34943K(314560K), 0.0147798 secs] 629907K->427001K(1013632K), 0.0152478 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T13:32:38.192+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 392057K(699072K)] 433387K(1013632K), 0.0009641 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.194+0800: [CMS-concurrent-mark-start]
2023-10-22T13:32:38.196+0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.196+0800: [CMS-concurrent-preclean-start]
2023-10-22T13:32:38.198+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.198+0800: [CMS-concurrent-abortable-preclean-start]
2023-10-22T13:32:38.221+0800: [GC (Allocation Failure) [ParNew: 314559K->34942K(314560K), 0.0153391 secs] 706617K->504137K(1013632K), 0.0160979 secs] [Times: user=0.00 sys=0.00, real=0.02 secs]
2023-10-22T13:32:38.267+0800: [GC (Allocation Failure) [ParNew: 314558K->34943K(314560K), 0.0152339 secs] 783753K->586934K(1013632K), 0.0156543 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
2023-10-22T13:32:38.311+0800: [GC (Allocation Failure) [ParNew: 314499K->34943K(314560K), 0.0158130 secs] 866490K->671899K(1013632K), 0.0162828 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]
2023-10-22T13:32:38.356+0800: [GC (Allocation Failure) [ParNew: 314559K->314559K(314560K), 0.0001828 secs][CMS2023-10-22T13:32:38.357+0800: [CMS-concurrent-abortable-preclean: 0.005/0.157 secs] [Times: user=0.39 sys=0.00, real=0.16 secs]
 (concurrent mode failure): 636955K->379920K(699072K), 0.0448748 secs] 951515K->379920K(1013632K), [Metaspace: 2593K->2593K(1056768K)], 0.0461902 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
执行结束!共生成对象次数:15694
Heap
 par new generation   total 314560K, used 11377K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K,   4% used [0x00000000c0000000, 0x00000000c0b1c618, 0x00000000d1110000)
  from space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
  to   space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330000, 0x00000000d5550000)
 concurrent mark-sweep generation total 699072K, used 379920K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2600K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 279K, capacity 386K, committed 512K, reserved 1048576K

前面几个GC已经很熟悉了，重点看下CMS GC这一块。CMS是针对Old区的GC策略。

2023-10-22T13:32:37.795+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 350160K(699072K)] 391368K(1013632K), 0.0004048 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.796+0800: [CMS-concurrent-mark-start]
2023-10-22T13:32:37.799+0800: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.799+0800: [CMS-concurrent-preclean-start]
2023-10-22T13:32:37.825+0800: [GC (Allocation Failure) [ParNew: 314559K->34944K(314560K), 0.0429650 secs] 664720K->467336K(1013632K), 0.0432853 secs] [Times: user=0.41 sys=0.06, real=0.04 secs]
.....
2023-10-22T13:32:37.801+0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
2023-10-22T13:32:37.801+0800: [CMS-concurrent-abortable-preclean-start]
2023-10-22T13:32:38.149+0800: [GC (CMS Final Remark) [YG occupancy: 129087 K (314560 K)][Rescan (parallel) , 0.0005396 secs][weak refs processing, 0.0000926 secs][class unloading, 0.0002457 secs][scrub symbol table, 0.0002998 secs][scrub string table, 0.0002303 secs][1 CMS-remark: 641109K(699072K)] 770197K(1013632K), 0.0021516 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.094+0800: [CMS-concurrent-sweep-start]
2023-10-22T13:32:38.095+0800: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2023-10-22T13:32:38.096+0800: [CMS-concurrent-reset-start]
2023-10-22T13:32:38.098+0800: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]

CMS-initial-mark：第一个阶段是CMS初始化标记的阶段。因为这个阶段只标记了根对象、根对象可达对象、跨区引用对象，所以时间非常快，可以看到是不到1ms的时间。
CMS-concurrent-mark-start、CMS-concurrent-mark：并发标记阶段（有产生STW）
CMS-concurrent-preclean-start、CMS-concurrent-preclean：并发预清理
CMS-concurrent-abortable-preclean-start：可取消的并发预清理
GC (CMS Final Remark)：最终标记（有产生STW）
CMS-concurrent-sweep-start、CMS-concurrent-sweep：并发清理
CMS-concurrent-reset-start、CMS-concurrent-reset：并发重置

过程中可以看到有YoungGC出现，因为CMS GC是针对老年代的垃圾回收算法，所以在CMS GC的过程中，有可能发生一次或者多次的YoungGC.

使用G1 GC

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xmx1g -Xms1g -XX:+UseG1GC jvm.test1.GCLogAnalysis

G1 GC的日志非常复杂，这里只贴出一部分

正在执行...
2023-10-22T16:12:10.331+0800: [GC pause (G1 Evacuation Pause) (young), 0.0044092 secs]
   [Parallel Time: 2.4 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 99.2, Avg: 99.4, Max: 99.5, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [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.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.9, Avg: 2.0, Max: 2.1, Diff: 0.2, Sum: 19.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.0, Avg: 2.1, Max: 2.3, Diff: 0.3, Sum: 21.1]
      [GC Worker End (ms): Min: 101.5, Avg: 101.5, Max: 101.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Migration: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.9 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 51.0M(51.0M)->0.0B(44.0M) Survivors: 0.0B->7168.0K Heap: 62.6M(1024.0M)->27.5M(1024.0M)]
 [Times: user=0.03 sys=0.11, real=0.04 secs]
 ......ss

为了简化查看，可以修改日志参数:

java -XX:+PrintGC -XX:+PrintGCDateStamps -Xmx1g -Xms1g -XX:+UseG1GC jvm.test1.GCLogAnalysis

简化的日志为：

正在执行...
2023-10-22T16:14:37.018+0800: [GC pause (G1 Evacuation Pause) (young) 63M->29M(1024M), 0.0048229 secs]
2023-10-22T16:14:37.033+0800: [GC pause (G1 Evacuation Pause) (young) 80M->52M(1024M), 0.0050392 secs]
2023-10-22T16:14:37.049+0800: [GC pause (G1 Evacuation Pause) (young) 106M->81M(1024M), 0.0059543 secs]
2023-10-22T16:14:37.073+0800: [GC pause (G1 Evacuation Pause) (young) 155M->112M(1024M), 0.0064226 secs]
2023-10-22T16:14:37.118+0800: [GC pause (G1 Evacuation Pause) (young) 237M->173M(1024M), 0.0079536 secs]
2023-10-22T16:14:37.172+0800: [GC pause (G1 Evacuation Pause) (young) 354M->249M(1024M), 0.0084156 secs]
2023-10-22T16:14:37.215+0800: [GC pause (G1 Evacuation Pause) (young) 425M->327M(1024M), 0.0091301 secs]
2023-10-22T16:14:37.269+0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 540M->413M(1024M), 0.0097816 secs]
2023-10-22T16:14:37.279+0800: [GC concurrent-root-region-scan-start]
2023-10-22T16:14:37.281+0800: [GC concurrent-root-region-scan-end, 0.0008608 secs]
2023-10-22T16:14:37.281+0800: [GC concurrent-mark-start]
2023-10-22T16:14:37.283+0800: [GC concurrent-mark-end, 0.0019074 secs]
2023-10-22T16:14:37.283+0800: [GC remark, 0.0012023 secs]
2023-10-22T16:14:37.285+0800: [GC cleanup 426M->295M(1024M), 0.0010499 secs]
......

在使用G1 GC的时候要注意，一定要防止产生FullGC导致串行化，一旦产生FullGC，G1GC就会退化为串行GC，对性能产生很大的影响。

526互联

[JVM]GC日志解读解析

GC日志解读解析

示例代码

日志解读