切换语言为：繁体
网站地图
详细解读 GC 日志

详细解读 GC 日志

  • 爱糖宝
  • 2024-06-27
  • 2063
  • 0
  • 0 
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

启动参数

 -Xms20m -Xmx20m -Xmn10M  -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDateStamps -XX:+UseSerialGC

-XX:+HeapDumpOnOutOfMemoryError

当设置此选项时，只要JVM遇到内存不足错误（OutOfMemoryError），它就会生成一个堆转储。此功能对于故障排查和诊断应用程序中的内存问题特别有用，因为它允许开发者和系统管理员分析内存耗尽那一刻的内存状态。

正在执行...
2024-06-23T19:25:24.049-0800: [GC (Allocation Failure) 2024-06-23T19:25:24.049-0800: [DefNew: 8165K->1024K(9216K), 0.0024556 secs] 8165K->2791K(19456K), 0.0025117 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2024-06-23T19:25:24.065-0800: [GC (Allocation Failure) 2024-06-23T19:25:24.065-0800: [DefNew: 9202K->9202K(9216K), 0.0000151 secs]2024-06-23T19:25:24.065-0800: [Tenured: 8352K->10102K(10240K), 0.0025353 secs] 17555K->12336K(19456K), [Metaspace: 2962K->2962K(1056768K)], 0.0025851 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-23T19:25:24.086-0800: [Full GC (Allocation Failure) 2024-06-23T19:25:24.086-0800: [Tenured: 10153K->10131K(10240K), 0.0020385 secs] 19103K->19081K(19456K), [Metaspace: 2962K->2962K(1056768K)], 0.0020657 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 


Heap
 def new generation   total 9216K, used 8996K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K, 100% used [0x00000007bec00000, 0x00000007bf400000, 0x00000007bf400000)
  from space 1024K,  78% used [0x00000007bf500000, 0x00000007bf5c9288, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 tenured generation   total 10240K, used 10131K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  98% used [0x00000007bf600000, 0x00000007bffe4fd8, 0x00000007bffe5000, 0x00000007c0000000)
 Metaspace       used 2993K, capacity 4490K, committed 4864K, reserved 1056768K
  class space    used 318K, capacity 386K, committed 512K, reserved 1048576K

Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOf(Arrays.java:3332)
	at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
	at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:674)
	at java.lang.StringBuilder.append(StringBuilder.java:208)
	at com.core.gc.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:62)
	at com.core.gc.GCLogAnalysis.main(GCLogAnalysis.java:31)
Disconnected from the target VM, address: '127.0.0.1:57434', transport: 'socket'

Minor GC 日志分析

这次年轻代 GC 事件对应的日志内容：

2024-06-23T19:25:24.049-0800: 
[GC (Allocation Failure) 
2024-06-23T19:25:24.049-0800: 
[DefNew: 8165K->1024K(9216K), 0.0024556 secs] 8165K->2791K(19456K), 0.0025117 secs] 
[Times: user=0.01 sys=0.00, real=0.01 secs]

从中可以解读出这些信息：

  1. 2024-06-23T19:25:24.049-0800：GC 事件开始的时间点。其中 -0800 表示当前时区为东八区，这只是一个标识，方便我们直观判断 GC 发生的时间点。

  2. GC 用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次 Minor GC ，即年轻代 GC。Allocation Failure 表示触发 GC 的原因。本次 GC 事件，是由于对象分配失败，年轻代中没有空间来存放新生成的对象引起的。

  3. DefNew 表示垃圾收集器的名称。这个名字表示：年轻代使用的单线程、标记—复制、STW 垃圾收集器。8165K->1024K(9216K) 表示在垃圾收集之前和之后的年轻代使用量。(9216K) 表示年轻代的总空间大小。

  4. 8165K->2791K(19456K)表示在垃圾收集之前和之后整个堆内存的使用情况。(19456K) 则表示堆内存可用的总空间大小。进一步分析可知：GC 之后堆内存使用量为 14%。

  5. 0.0025117 secs：GC 事件持续的时间，以秒为单位。

  6. [Times: user=0.01 sys=0.00，real=0.01 secs]：此次 GC 事件的持续时间，通过三个部分来衡量。user 部分表示所有 GC 线程消耗的 CPU 时间；sys 部分表示系统调用和系统等待事件消耗的时间。real 则表示应用程序暂停的时间。因为串行垃圾收集器（Serial Garbage Collector）只使用单个线程，所以这里 real=user+system，0.01 秒也就是 10 毫秒。

这个暂停时间对大部分系统来说可以接受，但对某些延迟敏感的系统就不太理想了，比如实时的游戏服务、高频交易业务，10ms 暂停导致的延迟可能会要了亲命。

这样解读之后，我们可以分析 JVM 在 GC 事件中的内存使用以及变化情况。

在此次垃圾收集之前，堆内存总的使用量为 8165K，其中年轻代使用了 8165K。可以算出，GC 之前老年代空间的使用量为 0。

这些数字中蕴含了更重要的信息：

  • GC 前后对比，年轻代的使用量为 从8165K减少到1024K

  • 但堆内存的总使用量 从8105K减少到2791K

可以算出，从年轻代提升到老年代的对象占用了“2791K-1024K=1767K”的内存空间。

Full GC 日志分析

分析完第一次 GC 事件之后，我们心中应该有个大体的模式了。一起来看看另一次 GC 事件的日志：

2024-06-23T19:25:24.069-0800:
[Full GC (Allocation Failure)
2024-06-23T19:25:24.069-0800: 
[Tenured: 10102K->10037K(10240K), 0.0025304 secs] 19249K->15432K(19456K), 
[Metaspace: 2962K->2962K(1056768K)], 0.0025630 secs] 
[Times: user=0.00 sys=0.00, real=0.01 secs]

从中可以解读出这些信息：

  1. 2024-06-23T19:25:24.069-0800：GC 事件开始的时间。

  2. Tenured：用于清理老年代空间的垃圾收集器名称。Tenured 表明使用的是单线程的 STW 垃圾收集器，使用的算法为“标记—清除—整理（mark-sweep-compact）”。 10102K->10037K(10240K)表示 GC 前后老年代的使用量，以及老年代的空间大小。0.0025304 secs 是清理老年代所花的时间。

  3. 19249K->15432K(19456K)：在 GC 前后整个堆内存部分的使用情况，以及可用的堆空间大小。

  4. [Metaspace: 2962K->2962K(1056768K)], 0.0025630 secs]：Metaspace 空间的变化情况。可以看出，此次 GC 过程中 Metaspace 也没有什么变化。

  5. [Times: user=0.00 sys=0.00, real=0.01 secs] ：GC 事件的持续时间，分为 user、sys、real 三个部分。因为串行垃圾收集器只使用单个线程，因此“real=user+system”。10 毫秒的暂停时间。这个时间跟什么有关系呢？答案是：GC 时间，与 GC 后存活对象的总数量关系最大。

总结：

Full GC，我们主要关注 GC 之后内存使用量是否下降，其次关注暂停时间。

Parallel GC 日志解读

并行垃圾收集器对年轻代使用“标记—复制（mark-copy）”算法，对老年代使用“标记—清除—整理（mark-sweep-compact）”算法。

年轻代和老年代的垃圾回收时都会触发 STW 事件，暂停所有的应用线程，再来执行垃圾收集。在执行“标记”和“复制/整理”阶段时都使用多个线程，因此得名“Parallel”。

通过多个 GC 线程并行执行的方式，能使 JVM 在多 CPU 平台上的 GC 时间大幅减少。

通过命令行参数 -XX:ParallelGCThreads=NNN 可以指定 GC 线程的数量，其默认值为 CPU 内核数量。

下面的三组命令行参数是等价的，都可用来指定并行垃圾收集器：

-XX:+UseParallelGC
-XX:+UseParallelOldGC
-XX:+UseParallelGC -XX:+UseParallelOldGC

 -Xms20m -Xmx20m -Xmn10M  -XX:SurvivorRatio=8 -XX:+PrintCommandLineFlags -XX:+PrintGCDetails -XX:+UseParallelGC -XX:+UseParallelOldGC

并行垃圾收集器适用于多核服务器，其主要目标是增加系统吞吐量（也就是降低 GC 总体消耗的时间）。为了达成这个目标，会使用尽可能多的 CPU 资源：

  • 在 GC 事件执行期间，所有 CPU 内核都在并行地清理垃圾，所以暂停时间相对来说更短；

  • 在两次 GC 事件中间的间隔期，不会启动 GC 线程，所以这段时间内不会消耗任何系统资源。

另一方面，因为并行 GC 的所有阶段都不能中断，所以并行 GC 很可能会出现长时间的卡顿。

长时间卡顿的意思，就是并行 GC 启动后，一次性完成所有的 GC 操作，所以单次暂停的时间较长。

假如系统延迟是非常重要的性能指标，那么就应该选择其他垃圾收集器。

执行上面的命令行，让我们看看并行垃圾收集器的 GC 日志长什么样子：

正在执行...
2024-06-23T21:30:04.236-0800: [GC (Allocation Failure) [PSYoungGen: 9171K->995K(9216K)] 13928K->8240K(19456K), 0.0015653 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2024-06-23T21:30:04.274-0800: [Full GC (Ergonomics) [PSYoungGen: 7963K->7544K(9216K)] [ParOldGen: 10172K->10138K(10240K)] 18135K->17683K(19456K), [Metaspace: 3216K->3216K(1056768K)], 0.0018609 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 

2024-06-23T21:30:04.276-0800: [Full GC (Allocation Failure) [PSYoungGen: 7544K->7544K(9216K)] [ParOldGen: 10138K->10113K(10240K)] 17683K->17658K(19456K), [Metaspace: 3216K->3216K(1056768K)], 0.0036978 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 


Heap
 PSYoungGen      total 9216K, used 7737K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 8192K, 94% used [0x00000007bf600000,0x00000007bfd8e690,0x00000007bfe00000)
  from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
  to   space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
 ParOldGen       total 10240K, used 10113K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  object space 10240K, 98% used [0x00000007bec00000,0x00000007bf5e0718,0x00000007bf600000)
 Metaspace       used 3247K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 360K, capacity 388K, committed 512K, reserved 1048576K
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at com.core.gc.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:54)
	at com.core.gc.GCLogAnalysis.main(GCLogAnalysis.java:31)

Minor GC 日志分析

前面的 GC 事件是发生在年轻代 Minor GC：

2024-06-23T21:30:04.236-0800: 
[GC (Allocation Failure) [PSYoungGen: 9171K->995K(9216K)] 
13928K->8240K(19456K), 0.0015653 secs] 
[Times: user=0.01 sys=0.00, real=0.00 secs]

解读如下：

  1. 2024-06-23T21:30:04.225-0800：GC 事件开始的时间。

  2. GC：用来区分 Minor GC 还是 Full GC 的标志。这里是一次 Minor GC。

  3. PSYoungGen：垃圾收集器的名称。这个名字表示的是在年轻代中使用并行的“标记—复制（mark-copy）”，全线暂停（STW）垃圾收集器。

  4. 9171K->995K(9216K) 表示 GC 前后的年轻代使用量，以及年轻代的总大小。

  5. 13928K->8240K(19456K) 则是 GC 前后整个堆内存的使用量，以及此时可用堆的总大小，GC 后堆内存使用率为 8240K/19456K=42%。

  6. [Times: user=0.01 sys=0.00，real=0.00 secs]：GC 事件的持续时间，通过三个部分来衡量。user 表示 GC 线程所消耗的总 CPU 时间，sys 表示操作系统调用和系统等待事件所消耗的时间； real 则表示应用程序实际暂停的时间。因为并不是所有的操作过程都能全部并行，所以在 Parallel GC 中，real 约等于 user+system/GC 线程数。我的机器是 16 个物理线程，所以默认是 16 个 GC 线程。

通过这部分日志可以简单算出：

  • 在 GC 之前，堆内存总使用量为 13928K，其中年轻代为 9171K，那么可以算出老年代使用量为 4757k。

  • GC 完成后，年轻代使用量减少了 9171K-995K=8176K，总的堆内存使用量减少了 13928K-8240k=5688K，老年代的使用量为：8240K-995K=7245K。

Full GC 日志分析

前面介绍了并行 GC 清理年轻代的 GC 日志，下面来看看清理整个堆内存的 GC 日志：

2024-06-23T21:30:04.274-0800: 
[Full GC (Ergonomics) 
[PSYoungGen: 7963K->7544K(9216K)]
[ParOldGen: 10172K->10138K(10240K)] 
18135K->17683K(19456K), 
[Metaspace: 3216K->3216K(1056768K)], 0.0018609 secs]
[Times: user=0.02 sys=0.01, real=0.00 secs]

解读一下：

  1. 2024-06-23T21:30:04.274-0800：GC 事件开始的时间。

  2. Full GC：完全 GC 的标志。Full GC 表明本次 GC 清理年轻代和老年代，Ergonomics 是触发 GC 的原因，表示 JVM 内部环境认为此时可以进行一次垃圾收集。

  3. [PSYoungGen: 7963K->7544K(9216K)]：和上面的示例一样，清理年轻代的垃圾收集器是名为“PSYoungGen”的 STW 收集器，采用“标记—复制（mark-copy）”算法。年轻代使用量从 7963K->7544K(9216K)。

  4. ParOldGen：用于清理老年代空间的垃圾收集器类型。在这里使用的是名为 ParOldGen 的垃圾收集器，这是一款并行 STW 垃圾收集器，算法为“标记—清除—整理（mark-sweep-compact）”。10172K->10138K(10240K)：在 GC 前后老年代内存的使用情况以及老年代空间大小。简单计算一下，GC 之前，老年代使用率为 10172K/10240K=99%，GC 后老年代使用率 10138K/10240K=99%。

  5. [Metaspace: 3216K->3216K(1056768K)]：前面我们也看到了关于 Metaspace 空间的类似信息。可以看出，在 GC 事件中 Metaspace 里面没有回收任何对象。

  6. 0.0018609 secs：GC 事件持续的时间，以秒为单位。

  7. [Times: user=0.02 sys=0.01，real=0.00 secs]：GC 事件的持续时间，含义参见前面。

Full GC 和 Minor GC 的区别是很明显的，此次 GC 事件除了处理年轻代，还清理了老年代和 Metaspace。Full GC 时我们更关注老年代的使用量有没有下降，以及下降了多少。如果 FullGC 之后内存不怎么下降，使用率还很高，那就说明系统有问题了。

CMS

CMS 也可称为“并发标记清除垃圾收集器”。其设计目标是避免在老年代 GC 时出现长时间的卡顿。默认情况下，CMS 使用的并发线程数等于 CPU 内核数的 1/4。

 -Xms200m -Xmx200m -Xmn100M  -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC

正在执行...
2024-06-26T10:53:30.082-0800: [GC (Allocation Failure) 2024-06-26T10:53:30.082-0800: [ParNew: 91710K->10240K(92160K), 0.0156856 secs] 134966K->81704K(194560K), 0.0157223 secs] [Times: user=0.19 sys=0.01, real=0.01 secs] 


2024-06-26T10:53:30.395-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102294K(102400K)] 186201K(194560K), 0.0003330 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.395-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.396-0800: [CMS-concurrent-preclean-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.396-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.396-0800: [GC (CMS Final Remark) [YG occupancy: 90992 K (92160 K)]2024-06-26T10:53:30.396-0800: [Rescan (parallel) , 0.0005008 secs]2024-06-26T10:53:30.397-0800: [weak refs processing, 0.0000527 secs]2024-06-26T10:53:30.397-0800: [class unloading, 0.0002036 secs]2024-06-26T10:53:30.397-0800: [scrub symbol table, 0.0003308 secs]2024-06-26T10:53:30.397-0800: [scrub string table, 0.0001811 secs][1 CMS-remark: 102294K(102400K)] 193286K(194560K), 0.0013165 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.398-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.398-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.398-0800: [CMS-concurrent-reset-start]
2024-06-26T10:53:30.398-0800: [GC (Allocation Failure) 2024-06-26T10:53:30.398-0800: [ParNew: 92090K->92090K(92160K), 0.0000189 secs]2024-06-26T10:53:30.398-0800: [CMS2024-06-26T10:53:30.398-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
: 102294K->102208K(102400K), 0.0173464 secs] 194384K->187616K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0174094 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

2024-06-26T10:53:30.417-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.417-0800: [CMS: 102208K->102389K(102400K), 0.0111709 secs] 194306K->187354K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0112097 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 


2024-06-26T10:53:30.428-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102389K(102400K)] 187860K(194560K), 0.0003011 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.429-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.429-0800: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.429-0800: [CMS-concurrent-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.430-0800: [GC (CMS Final Remark) [YG occupancy: 90976 K (92160 K)]2024-06-26T10:53:30.430-0800: [Rescan (parallel) , 0.0003618 secs]2024-06-26T10:53:30.430-0800: [weak refs processing, 0.0000521 secs]2024-06-26T10:53:30.430-0800: [class unloading, 0.0002041 secs]2024-06-26T10:53:30.430-0800: [scrub symbol table, 0.0003458 secs]2024-06-26T10:53:30.431-0800: [scrub string table, 0.0001662 secs][1 CMS-remark: 102389K(102400K)] 193366K(194560K), 0.0011737 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.431-0800: [GC (Allocation Failure) 2024-06-26T10:53:30.431-0800: [ParNew: 92021K->92021K(92160K), 0.0000191 secs]2024-06-26T10:53:30.431-0800: [CMS: 102389K->102389K(102400K), 0.0082622 secs] 194410K->189334K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0083172 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.440-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.440-0800: [CMS: 102389K->102197K(102400K), 0.0174041 secs] 194034K->191413K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0174419 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.458-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102197K(102400K)] 192037K(194560K), 0.0002733 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.458-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.459-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.459-0800: [CMS2024-06-26T10:53:30.460-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 102197K->101900K(102400K), 0.0131458 secs] 194260K->191492K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0131832 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2024-06-26T10:53:30.472-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.472-0800: [CMS: 102384K->102397K(102400K), 0.0177625 secs] 194530K->191964K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0177992 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 


2024-06-26T10:53:30.490-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102397K(102400K)] 191982K(194560K), 0.0003156 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.491-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.491-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.491-0800: [CMS2024-06-26T10:53:30.493-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 102397K->102365K(102400K), 0.0141003 secs] 194457K->192500K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0141493 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.506-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.506-0800: [CMS: 102365K->102365K(102400K), 0.0022801 secs] 194523K->193944K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0023275 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.508-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102365K(102400K)] 194120K(194560K), 0.0002318 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.509-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.509-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.509-0800: [CMS2024-06-26T10:53:30.511-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 102365K->102352K(102400K), 0.0091659 secs] 194157K->193786K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0091981 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.518-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.518-0800: [CMS: 102352K->102352K(102400K), 0.0019563 secs] 194427K->194364K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0019905 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.520-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.520-0800: [CMS: 102352K->102331K(102400K), 0.0091525 secs] 194364K->194342K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0091832 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 


java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid5853.hprof ...
2024-06-26T10:53:30.530-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102331K(102400K)] 194342K(194560K), 0.0002874 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.530-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.893-0800: [CMS-concurrent-mark: 0.001/0.363 secs] [Times: user=0.30 sys=0.05, real=0.36 secs] 
2024-06-26T10:53:30.893-0800: [CMS-concurrent-preclean-start]
Heap dump file created [199649283 bytes in 0.364 secs]
2024-06-26T10:53:30.894-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.894-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.894-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.894-0800: [GC (CMS Final Remark) [YG occupancy: 92011 K (92160 K)]2024-06-26T10:53:30.894-0800: [Rescan (parallel) , 0.0003777 secs]2024-06-26T10:53:30.894-0800: [weak refs processing, 0.0000442 secs]2024-06-26T10:53:30.894-0800: [class unloading, 0.0001743 secs]2024-06-26T10:53:30.894-0800: [scrub symbol table, 0.0002701 secs]2024-06-26T10:53:30.895-0800: [scrub string table, 0.0001329 secs][1 CMS-remark: 102331K(102400K)] 194342K(194560K), 0.0010415 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.895-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.895-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.895-0800: [CMS-concurrent-reset-start]
2024-06-26T10:53:30.895-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 92160K, used 92074K [0x00000007b3800000, 0x00000007b9c00000, 0x00000007b9c00000)
  eden space 81920K, 100% used [0x00000007b3800000, 0x00000007b8800000, 0x00000007b8800000)
  from space 10240K,  99% used [0x00000007b9200000, 0x00000007b9beaaf0, 0x00000007b9c00000)
  to   space 10240K,   0% used [0x00000007b8800000, 0x00000007b8800000, 0x00000007b9200000)
 concurrent mark-sweep generation total 102400K, used 102331K [0x00000007b9c00000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2997K, capacity 4490K, committed 4864K, reserved 1056768K
  class space    used 318K, capacity 386K, committed 512K, reserved 1048576K
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at com.core.gc.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:54)
	at com.core.gc.GCLogAnalysis.main(GCLogAnalysis.java:31)
Disconnected from the target VM, address: '127.0.0.1:55200', transport: 'socket'

Minor GC 日志分析

2024-06-26T10:53:30.082-0800: 
[GC (Allocation Failure) 
2024-06-26T10:53:30.082-0800: [ParNew: 91710K->10240K(92160K), 0.0156856 secs] 134966K->81704K(194560K), 0.0157223 secs] 
[Times: user=0.19 sys=0.01, real=0.01 secs]

我们一起来解读：

  1. 2024-06-26T10:53:30.082-0800：GC 事件开始的时间。

  2. GC (Allocation Failure)：用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次 Minor GC；Allocation Failure 表示触发 GC 的原因。本次 GC 事件，是由于年轻代可用空间不足，新对象的内存分配失败引起的。

  3. ParNew: 91710K->10240K(92160K), 0.0156856 secs]：其中 ParNew 是垃圾收集器的名称，表示在年轻代中使用的“并行的标记—复制（mark-copy）”垃圾收集器，专门设计了用来配合 CMS 垃圾收集器，因为 CMS 只负责回收老年代。后面的数字表示 GC 前后的年轻代使用量变化，以及年轻代的总大小。0.0156856 secs 是消耗的时间。

  4. 134966K->81704K(194560K), 0.0157223 secs：表示 GC 前后堆内存的使用量变化，以及堆内存空间的大小。消耗的时间是 0.0157223 secs。

  5. [Times: user=0.19 sys=0.01, real=0.01 secs] ：GC 事件的持续时间。user 是 GC 线程所消耗的总 CPU 时间；sys 是操作系统调用和系统等待事件消耗的时间；应用程序实际暂停的时间 real ~= (user + sys)/GC线程数。

进一步计算和分析可以得知

  • GC 之前，年轻代使用量为 91710K/92160K=99%。堆内存的使用率为 134966K/194560K=69%。稍微估算一下，老年代的使用率为：(134966K-91710K)/(194560K-92160K)=(43256K /102400K)=42%。

  • GC 之后，年轻代使用量为 10240K，下降了 81470K。堆内存使用量为 81704K ，只下降了 53262K。两个下降值相减，就是年轻代提升到老年代的内存量：81704K-10240K=71464K。

Full GC 日志分析

实际上这次截取的年轻代 GC 日志和 FullGC 日志是紧连着的，我们从间隔时间也能大致看出来。

CMS 的日志是一种完全不同的格式，并且很长，因为 CMS 对老年代进行垃圾收集时每个阶段都会有自己的日志。为了简洁，我们将对这部分日志按照阶段依次介绍。

首先来看 CMS 这次 FullGC 的日志：

2024-06-26T10:53:30.395-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102294K(102400K)] 186201K(194560K), 0.0003330 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.395-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.396-0800: [CMS-concurrent-preclean-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.396-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.396-0800: [GC (CMS Final Remark) [YG occupancy: 90992 K (92160 K)]2024-06-26T10:53:30.396-0800: [Rescan (parallel) , 0.0005008 secs]2024-06-26T10:53:30.397-0800: [weak refs processing, 0.0000527 secs]2024-06-26T10:53:30.397-0800: [class unloading, 0.0002036 secs]2024-06-26T10:53:30.397-0800: [scrub symbol table, 0.0003308 secs]2024-06-26T10:53:30.397-0800: [scrub string table, 0.0001811 secs][1 CMS-remark: 102294K(102400K)] 193286K(194560K), 0.0013165 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.398-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.398-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.398-0800: [CMS-concurrent-reset-start]
2024-06-26T10:53:30.398-0800: [GC (Allocation Failure) 2024-06-26T10:53:30.398-0800: [ParNew: 92090K->92090K(92160K), 0.0000189 secs]2024-06-26T10:53:30.398-0800: [CMS2024-06-26T10:53:30.398-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
: 102294K->102208K(102400K), 0.0173464 secs] 194384K->187616K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0174094 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

2024-06-26T10:53:30.417-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.417-0800: [CMS: 102208K->102389K(102400K), 0.0111709 secs] 194306K->187354K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0112097 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 


2024-06-26T10:53:30.428-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102389K(102400K)] 187860K(194560K), 0.0003011 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.429-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.429-0800: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.429-0800: [CMS-concurrent-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.430-0800: [GC (CMS Final Remark) [YG occupancy: 90976 K (92160 K)]2024-06-26T10:53:30.430-0800: [Rescan (parallel) , 0.0003618 secs]2024-06-26T10:53:30.430-0800: [weak refs processing, 0.0000521 secs]2024-06-26T10:53:30.430-0800: [class unloading, 0.0002041 secs]2024-06-26T10:53:30.430-0800: [scrub symbol table, 0.0003458 secs]2024-06-26T10:53:30.431-0800: [scrub string table, 0.0001662 secs][1 CMS-remark: 102389K(102400K)] 193366K(194560K), 0.0011737 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.431-0800: [GC (Allocation Failure) 2024-06-26T10:53:30.431-0800: [ParNew: 92021K->92021K(92160K), 0.0000191 secs]2024-06-26T10:53:30.431-0800: [CMS: 102389K->102389K(102400K), 0.0082622 secs] 194410K->189334K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0083172 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.440-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.440-0800: [CMS: 102389K->102197K(102400K), 0.0174041 secs] 194034K->191413K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0174419 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.458-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102197K(102400K)] 192037K(194560K), 0.0002733 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.458-0800: [CMS-concurrent-mark-start]

2024-06-26T10:53:30.459-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.459-0800: [CMS2024-06-26T10:53:30.460-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 102197K->101900K(102400K), 0.0131458 secs] 194260K->191492K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0131832 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2024-06-26T10:53:30.472-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.472-0800: [CMS: 102384K->102397K(102400K), 0.0177625 secs] 194530K->191964K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0177992 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 


2024-06-26T10:53:30.490-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102397K(102400K)] 191982K(194560K), 0.0003156 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 


2024-06-26T10:53:30.491-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.491-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.491-0800: [CMS2024-06-26T10:53:30.493-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 102397K->102365K(102400K), 0.0141003 secs] 194457K->192500K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0141493 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.506-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.506-0800: [CMS: 102365K->102365K(102400K), 0.0022801 secs] 194523K->193944K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0023275 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.508-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102365K(102400K)] 194120K(194560K), 0.0002318 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.509-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.509-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.509-0800: [CMS2024-06-26T10:53:30.511-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 102365K->102352K(102400K), 0.0091659 secs] 194157K->193786K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0091981 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.518-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.518-0800: [CMS: 102352K->102352K(102400K), 0.0019563 secs] 194427K->194364K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0019905 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.520-0800: [Full GC (Allocation Failure) 2024-06-26T10:53:30.520-0800: [CMS: 102352K->102331K(102400K), 0.0091525 secs] 194364K->194342K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0091832 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 


java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid5853.hprof ...

Heap
 par new generation   total 92160K, used 92074K [0x00000007b3800000, 0x00000007b9c00000, 0x00000007b9c00000)
  eden space 81920K, 100% used [0x00000007b3800000, 0x00000007b8800000, 0x00000007b8800000)
  from space 10240K,  99% used [0x00000007b9200000, 0x00000007b9beaaf0, 0x00000007b9c00000)
  to   space 10240K,   0% used [0x00000007b8800000, 0x00000007b8800000, 0x00000007b9200000)
 concurrent mark-sweep generation total 102400K, used 102331K [0x00000007b9c00000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2997K, capacity 4490K, committed 4864K, reserved 1056768K
  class space    used 318K, capacity 386K, committed 512K, reserved 1048576K
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at com.core.gc.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:54)
	at com.core.gc.GCLogAnalysis.main(GCLogAnalysis.java:31)
Disconnected from the target VM, address: '127.0.0.1:55200', transport: 'socket'

在实际运行中，CMS 在进行老年代的并发垃圾回收时，可能会伴随着多次年轻代的 Minor GC（想想是为什么）。在这种情况下，Full GC 的日志中可能会掺杂着多次 Minor GC 事件。

阶段 1：Initial Mark（初始标记）

前面章节提到过，这个阶段伴随着 STW 暂停。初始标记的目标是标记所有的根对象，包括 GC ROOT 直接引用的对象，以及被年轻代中所有存活对象所引用的对象。后面这部分也非常重要，因为老年代是独立进行回收的。

先看这个阶段的日志：

2024-06-26T10:53:30.395-0800: 
[GC (CMS Initial Mark) 
[1 CMS-initial-mark: 102294K(102400K)] 186201K(194560K), 0.0003330 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

让我们简单解读一下：

  1. 2024-06-26T10:53:30.395-0800：参考前面的解读

  2. CMS Initial Mark：这个阶段的名称为“Initial Mark”，会标记所有的 GC Root。

  3. [1 CMS-initial-mark: 102294K(102400K)]：这部分数字表示老年代的使用量，以及老年代的空间大小。

  4. 186201K(194560K), 0.0003330 secs：当前堆内存的使用量，以及可用堆的大小、消耗的时间。可以看出这个时间非常短，只有 0.3 毫秒左右，因为要标记的这些 Root 数量很少。

  5. [Times: user=0.00 sys=0.00,real=0.00 secs]：初始标记事件暂停的时间，可以看到可以忽略不计。

阶段 2：Concurrent Mark（并发标记）

在并发标记阶段，CMS 从前一阶段“Initial Mark”找到的 ROOT 开始算起，遍历老年代并标记所有的存活对象。

看看这个阶段的 GC 日志：

2024-06-26T10:53:30.395-0800: [CMS-concurrent-mark-start]
2024-06-26T10:53:30.396-0800: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读一下：

  1. CMS-concurrent-mark：指明了是 CMS 垃圾收集器所处的阶段为并发标记（“Concurrent Mark”）。

  2. 0.000/0.000 secs：此阶段的持续时间，分别是 GC 线程消耗的时间和实际消耗的时间。

  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：Times 对并发阶段来说这些时间并没多少意义，因为是从并发标记开始时刻计算的，而这段时间应用线程也在执行，所以这个时间只是一个大概的值。

阶段 3：Concurrent Preclean（并发预清理）

此阶段同样是与应用线程并发执行的，不需要停止应用线程。

看看并发预清理阶段的 GC 日志：

2024-06-26T10:53:30.429-0800: [CMS-concurrent-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

简单解读：

  1. CMS-concurrent-preclean：表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标记阶段执行过程中发生了改变的对象。

  2. 0.000/0.000 secs：此阶段的持续时间，分别是 GC 线程运行时间和实际占用的时间。

  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：Times 这部分对并发阶段来说没多少意义，因为是从开始时间计算的，而这段时间内不仅 GC 线程在执行并发预清理，应用线程也在运行。

阶段 4：Concurrent Abortable Preclean（可取消的并发预清理）

此阶段也不停止应用线程，尝试在会触发 STW 的 Final Remark 阶段开始之前，尽可能地多干一些活。

本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某一个退出条件（如迭代次数、有用工作量、消耗的系统时间等等）。

看看 GC 日志：

2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean-start]
2024-06-26T10:53:30.430-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读：

  1. CMS-concurrent-abortable-preclean：指示此阶段的名称：“Concurrent Abortable Preclean”。

  2. 0.000/0.000 secs：此阶段 GC 线程的运行时间和实际占用的时间。从本质上讲，GC 线程试图在执行 STW 暂停之前等待尽可能长的时间。默认条件下，此阶段可以持续最长 5 秒钟的时间。

  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”这部分对并发阶段来说没多少意义，因为程序在并发阶段中持续运行。

此阶段完成的工作可能对 STW 停顿的时间有较大影响，并且有许多重要的配置选项和失败模式。

阶段 5：Final Remark（最终标记）

最终标记阶段是此次 GC 事件中的第二次（也是最后一次）STW 停顿。

本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能 GC 线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。

通常 CMS 会尝试在年轻代尽可能空的情况下执行 final remark 阶段，以免连续触发多次 STW 事件。

这部分的 GC 日志看起来稍微复杂一些：

2024-06-26T10:53:30.430-0800:
[GC (CMS Final Remark) 
[YG occupancy: 90976 K (92160 K)]
2024-06-26T10:53:30.430-0800: [Rescan (parallel) , 0.0003618 secs]
2024-06-26T10:53:30.430-0800: [weak refs processing, 0.0000521 secs]
2024-06-26T10:53:30.430-0800: [class unloading, 0.0002041 secs]
2024-06-26T10:53:30.430-0800: [scrub symbol table, 0.0003458 secs]
2024-06-26T10:53:30.431-0800: [scrub string table, 0.0001662 secs][1 CMS-remark: 102389K(102400K)] 193366K(194560K), 0.0011737 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs]

一起来进行解读：

  1. CMS Final Remark：这是此阶段的名称，最终标记阶段，会标记老年代中所有的存活对象，包括此前的并发标记过程中创建/修改的引用。

  2. YG occupancy: 90976 K (92160 K)：当前年轻代的使用量和总容量。

  3. [Rescan (parallel) ，0.0003618 secs]：在程序暂停后进行重新扫描（Rescan），以完成存活对象的标记。这部分是并行执行的，消耗的时间为 0.0003618 秒。

  4. weak refs processing, 0.0000521 secs：第一个子阶段，处理弱引用的持续时间。

  5. class unloading, 0.0002041 secs：第二个子阶段，卸载不使用的类，以及持续时间。

  6. scrub symbol table, 0.0003458 secs：第三个子阶段，清理符号表，即持有 class 级别 metadata 的符号表（symbol tables）。

  7. scrub string table, 0.0001662 secs：第四个子阶段， 清理内联字符串对应的 string tables。

  8. 1 CMS-remark: 102389K(102400K)：此阶段完成后老年代的使用量和总容量。

  9. 193366K(194560K), 0.0011737 secs：此阶段完成后，整个堆内存的使用量和总容量。

  10. [Times: user=0.00 sys=0.00,real=0.00 secs]：GC 事件的持续时间。

在这 5 个标记阶段完成后，老年代中的所有存活对象都被标记上了，接下来 JVM 会将所有不使用的对象清除，以回收老年代空间。

阶段 6：Concurrent Sweep（并发清除）

此阶段与应用程序并发执行，不需要 STW 停顿。目的是删除不再使用的对象，并回收他们占用的内存空间。

看看这部分的 GC 日志：

2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep-start]
2024-06-26T10:53:30.431-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读：

  1. CMS-concurrent-sweep：此阶段的名称，“Concurrent Sweep”，并发清除老年代中所有未被标记的对象、也就是不再使用的对象，以释放内存空间。

  2. 0.000/0.000 secs：此阶段的持续时间和实际占用的时间，这是一个四舍五入值，只精确到小数点后 3 位。

  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没有多少意义，因为是从并发标记开始时计算的，而这段时间内不仅是并发标记线程在执行，程序线程也在运行。

阶段 7：Concurrent Reset（并发重置）

此阶段与应用程序线程并发执行，重置 CMS 算法相关的内部数据结构，下一次触发 GC 时就可以直接使用。

对应的日志为：

2019-12-22T00:00:31.893-0800: 1.095:
  [CMS-concurrent-reset-start]
2019-12-22T00:00:31.894-0800: 1.096:
  [CMS-concurrent-reset: 0.000/0.000 secs]
  [Times: user=0.00 sys=0.00,real=0.00 secs]

2024-06-26T10:53:30.895-0800: [CMS-concurrent-reset-start]
2024-06-26T10:53:30.895-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

简单解读：

  1. CMS-concurrent-reset：此阶段的名称，“Concurrent Reset”，重置 CMS 算法的内部数据结构，为下一次 GC 循环做准备。

  2. 0.000/0.000 secs：此阶段的持续时间和实际占用的时间

  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的，而这段时间内不仅 GC 线程在运行，程序也在运行。

阶段 8：内存回收
2024-06-26T10:53:30.140-0800: [GC (Allocation Failure) 
2024-06-26T10:53:30.140-0800: [ParNew: 81602K->81602K(92160K), 0.0000186 secs]
2024-06-26T10:53:30.141-0800: [CMS: 99146K->102260K(102400K), 0.0142856 secs] 180749K->119626K(194560K), [Metaspace: 2966K->2966K(1056768K)], 0.0143465 secs] 
[Times: user=0.01 sys=0.00, real=0.01 secs]

  • 时间戳：2024-06-26T10:53:30.140-0800 - 表示GC事件开始的时间。

  • GC触发原因：(Allocation Failure) - 垃圾收集被触发是因为JVM无法为新对象分配内存，表明堆空间不足。

  • GC阶段：

  1. ParNew：这一阶段并行地收集新生代。数字 81602K->81602K(92160K) 表示：

    • GC前：新生代使用了81,602 KB。

    • GC后：仍然使用81,602 KB，表明这次周期内没有对象从这个区域被回收。

    • 新生代总大小：92,160 KB。

    • 持续时间：0.0000186 秒，非常短，表示新生代收集效率高。

  2. CMS：这一阶段并发地对老年代进行标记和清除。

    • CMS前：老年代使用了99,146 KB。

    • CMS后：使用量变为102,260 KB，说明有对象从新生代移入老年代，并且老年代中可能也进行了一定的清理。

    • 老年代总大小：102,400 KB。

    • 持续时间：0.0142856 秒，比ParNew阶段长，因为CMS收集器的标记和清除过程更复杂。

总体堆变化：

  • GC前：堆总使用量为180,749 KB。

  • GC后：堆总使用量略微减少到119,626 KB，显示通过CMS操作释放了一些内存，主要是在老年代。

元空间（Metaspace）：

  • GC前：Metaspace使用了2,966 KB。

  • GC后：仍为2,966 KB，表明元数据空间（存储类和类加载器信息）无显著变化。

  • Metaspace总容量：1,056,768 KB。

总结： 该日志记录了一个垃圾收集事件，其中新生代和老年代都被处理。新生代收集迅速但未释放任何空间，暗示可能是针对最近创建的短生命周期对象的小规模收集。CMS收集在老年代上执行，导致使用空间略有增加，可能是由于对象从新生代晋升以及可能的存活对象处理。元空间没有显著变化。整个GC操作耗时0.0143465秒，实际时间消耗小，表明资源在垃圾收集过程中得到了高效利用。

阶段 9：Full GC
2024-06-26T10:53:30.509-0800: 
[Full GC (Allocation Failure) 
2024-06-26T10:53:30.509-0800: [CMS2024-06-26T10:53:30.511-0800: [CMS-concurrent-mark: 0.001/0.002 secs] 
[Times: user=0.00 sys=0.00, real=0.01 secs] 

 (concurrent mode failure): 102365K->102352K(102400K), 0.0091659 secs] 194157K->193786K(194560K), 
 [Metaspace: 2966K->2966K(1056768K)], 0.0091981 secs] 
 
 [Times: user=0.01 sys=0.00, real=0.01 secs]

  1. Full GC (Allocation Failure): 这表明发生了一次因分配内存失败而触发的完全垃圾回收，这包括新生代和老年代的垃圾回收。

  2. CMS (concurrent mode failure): 在CMS收集器的使用过程中，出现"concurrent mode failure"意味着在并发标记阶段之后，CMS无法找到足够的空间来推广新生代的对象或者应对当前的内存分配请求，因此需要进行一次全局暂停的Full GC来解决这个问题。这里的“concurrent mode failure”是触发Full GC的直接原因。

  3. 垃圾回收前后堆内存的变化:

    • 老年代：从102,365 KB回收后变为102,352 KB，说明在老年代中仅回收了13KB的空间，这反映了Full GC对于解决空间问题的效果有限。

    • 总体堆：从194,157 KB回收后变为193,786 KB，整体上减少了371KB，这包括新生代和老年代的总变化。

    • 堆总大小：194,560 KB，表明这是堆的总可用容量。

  4. Metaspace: 元空间在GC前后没有变化，仍然是2,966 KB使用中，总容量为1,056,768 KB，表明这次GC并未影响到元数据的存储空间。

  5. 总耗时:

    • Full GC的实际执行时间（包括所有阶段）约为0.009秒，用户时间和系统时间都很低，表明大部分时间用于等待垃圾回收完成的真实时间（wall-clock time）。

综上所述，这是一个因CMS收集器在并发模式下未能成功管理内存分配，进而引发的全堆垃圾回收事件，尽管执行了Full GC，但释放的空间相对较小，说明可能面临对象存活率高的情况。

G1

 -Xms200m -Xmx200m -Xmn100M  -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDateStamps -XX:+UseG1GC

运行之后，我们看看 G1 的日志长什么样：

正在执行...

2024-06-26T10:53:30.714-0800: [GC pause (G1 Evacuation Pause) (young), 0.0137656 secs]
   [Parallel Time: 11.8 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 388.2, Avg: 388.4, Max: 388.5, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 1.5]
      [Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.2, Sum: 3.5]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 37]
      [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: 10.1, Avg: 10.5, Max: 11.0, Diff: 0.9, Sum: 135.9]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 6.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 11.1, Avg: 11.3, Max: 11.6, Diff: 0.4, Sum: 147.5]
      [GC Worker End (ms): Min: 399.7, Avg: 399.8, Max: 399.9, Diff: 0.2]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 1.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.0 ms]
   [Eden: 100.0M(100.0M)->0.0B(87.0M) Survivors: 0.0B->13.0M Heap: 124.0M(200.0M)->45.5M(200.0M)]
 [Times: user=0.03 sys=0.09, real=0.01 secs] 

 
2024-06-26T10:53:30.759-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0032206 secs]
   [Parallel Time: 2.4 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 433.5, Avg: 433.6, Max: 433.7, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.5]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
         [Processed Buffers: Min: 0, Avg: 1.4, Max: 3, Diff: 3, Sum: 18]
      [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.7, Avg: 1.7, Max: 1.8, Diff: 0.2, Sum: 22.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.9]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [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: 27.9]
      [GC Worker End (ms): Min: 435.7, Avg: 435.8, Max: 435.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 40.0M(87.0M)->0.0B(87.0M) Survivors: 13.0M->13.0M Heap: 125.6M(200.0M)->95.1M(200.0M)]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.763-0800: [GC concurrent-root-region-scan-start]
2024-06-26T10:53:30.763-0800: [GC concurrent-root-region-scan-end, 0.0000854 secs]

2024-06-26T10:53:30.763-0800: [GC concurrent-mark-start]
2024-06-26T10:53:30.764-0800: [GC concurrent-mark-end, 0.0008582 secs]

2024-06-26T10:53:30.764-0800: [GC remark 2024-06-26T10:53:30.764-0800: [Finalize Marking, 0.0003093 secs] 2024-06-26T10:53:30.764-0800: [GC ref-proc, 0.0001091 secs] 2024-06-26T10:53:30.764-0800: [Unloading, 0.0005196 secs], 0.0011327 secs]
 [Times: user=0.01 sys=0.01, real=0.00 secs] 
2024-06-26T10:53:30.765-0800: [GC cleanup 100M->100M(200M), 0.0006160 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 


2024-06-26T10:53:30.776-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0008265 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 450.7, Avg: 450.8, Max: 450.8, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 1.4, Max: 3, Diff: 3, Sum: 18]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
         [Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 18]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 2.2]
      [GC Worker End (ms): Min: 450.9, Avg: 450.9, Max: 451.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 3072.0K(100.0M)->0.0B(99.0M) Survivors: 0.0B->1024.0K Heap: 161.2M(200.0M)->159.5M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.777-0800: [GC concurrent-root-region-scan-start]
2024-06-26T10:53:30.777-0800: [GC concurrent-root-region-scan-end, 0.0000393 secs]
2024-06-26T10:53:30.777-0800: [GC concurrent-mark-start]
2024-06-26T10:53:30.778-0800: [GC concurrent-mark-end, 0.0007308 secs]
2024-06-26T10:53:30.778-0800: [GC remark 2024-06-26T10:53:30.778-0800: [Finalize Marking, 0.0002496 secs] 2024-06-26T10:53:30.779-0800: [GC ref-proc, 0.0001081 secs] 2024-06-26T10:53:30.779-0800: [Unloading, 0.0004663 secs], 0.0010770 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.779-0800: [GC cleanup 165M->165M(200M), 0.0006007 secs]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 


2024-06-26T10:53:30.783-0800: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0010670 secs]
   [Parallel Time: 0.4 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 456.9, Avg: 456.9, Max: 457.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.8]
         [Processed Buffers: Min: 1, Avg: 2.0, Max: 3, Diff: 2, Sum: 26]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 3.7]
      [GC Worker End (ms): Min: 457.2, Avg: 457.2, Max: 457.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 18.0M(99.0M)->0.0B(100.0M) Survivors: 1024.0K->0.0B Heap: 180.1M(200.0M)->175.8M(200.0M)]
 [Times: user=0.00 sys=0.01, real=0.00 secs] 

2024-06-26T10:53:30.785-0800: [GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0009276 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 458.8, Avg: 458.8, Max: 458.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
         [Processed Buffers: Min: 0, Avg: 1.6, Max: 3, Diff: 3, Sum: 21]
      [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: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 2.9]
      [GC Worker End (ms): Min: 459.0, Avg: 459.1, Max: 459.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 4096.0K(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 180.4M(200.0M)->180.4M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.786-0800: [Full GC (Allocation Failure)  180M->110M(200M), 0.0120432 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 180.4M(200.0M)->110.6M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2024-06-26T10:53:30.799-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0011468 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 472.8, Avg: 472.9, Max: 473.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 2]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 1.7, Max: 2, Diff: 1, Sum: 22]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 2.3]
      [GC Worker End (ms): Min: 473.1, Avg: 473.1, Max: 473.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 4096.0K(100.0M)->0.0B(99.0M) Survivors: 0.0B->1024.0K Heap: 114.2M(200.0M)->111.5M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.800-0800: [GC concurrent-root-region-scan-start]
2024-06-26T10:53:30.800-0800: [GC concurrent-root-region-scan-end, 0.0000881 secs]
2024-06-26T10:53:30.800-0800: [GC concurrent-mark-start]
2024-06-26T10:53:30.800-0800: [GC concurrent-mark-end, 0.0005770 secs]
2024-06-26T10:53:30.801-0800: [GC remark 2024-06-26T10:53:30.801-0800: [Finalize Marking, 0.0006762 secs] 2024-06-26T10:53:30.801-0800: [GC ref-proc, 0.0001070 secs] 2024-06-26T10:53:30.801-0800: [Unloading, 0.0004616 secs], 0.0014337 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.802-0800: [GC cleanup 119M->119M(200M), 0.0005719 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 


2024-06-26T10:53:30.974-0800: [Full GC (Allocation Failure)  157M->155M(200M), 0.0022943 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 157.3M(200.0M)->155.9M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.977-0800: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0009059 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 651.3, Avg: 651.3, Max: 651.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 2]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 19]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 2.5]
      [GC Worker End (ms): Min: 651.5, Avg: 651.5, Max: 651.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.9M(200.0M)->156.9M(200.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.978-0800: [Full GC (Allocation Failure)  156M->155M(200M), 0.0027476 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.9M(200.0M)->155.6M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 

2024-06-26T10:53:30.981-0800: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0009689 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 655.3, Avg: 655.4, Max: 655.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 2]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 19]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 2.6]
      [GC Worker End (ms): Min: 655.5, Avg: 655.6, Max: 655.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.6M(200.0M)->156.6M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.982-0800: [Full GC (Allocation Failure)  156M->155M(200M), 0.0023342 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.6M(200.0M)->155.8M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.985-0800: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0008902 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 659.0, Avg: 659.0, Max: 659.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 2]
      [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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 20]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 2.5]
      [GC Worker End (ms): Min: 659.2, Avg: 659.2, Max: 659.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.8M(200.0M)->156.8M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

2024-06-26T10:53:30.986-0800: [Full GC (Allocation Failure)  156M->155M(200M), 0.0022666 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.8M(200.0M)->155.8M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.988-0800: [Full GC (Allocation Failure)  155M->155M(200M), 0.0021933 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 155.8M(200.0M)->155.8M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 



2024-06-26T10:53:30.284-0800: [Full GC (Allocation Failure)  155M->363K(200M), 0.0020527 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 155.8M(200.0M)->363.4K(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-06-26T10:53:30.286-0800: [GC concurrent-mark-abort]


Heap
 garbage-first heap   total 204800K, used 363K [0x00000007b3800000, 0x00000007b3900640, 0x00000007c0000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 2997K, capacity 4490K, committed 4864K, reserved 1056768K
  class space    used 318K, capacity 386K, committed 512K, reserved 1048576K


Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
   at java.util.Arrays.copyOfRange(Arrays.java:3664)
   at java.lang.String.<init>(String.java:207)
   at java.lang.StringBuilder.toString(StringBuilder.java:407)
   at com.core.gc.GCLogAnalysis.generateGarbage(GCLogAnalysis.java:64)
   at com.core.gc.GCLogAnalysis.main(GCLogAnalysis.java:31)
Disconnected from the target VM, address: '127.0.0.1:60611', transport: 'socket'

以上是摘录的一部分 GC 日志信息。

Evacuation Pause: (young)（纯年轻代模式转移暂停）

当年轻代空间用满后，应用线程会被暂停，年轻代内存块中的存活对象被拷贝到存活区。如果还没有存活区，则任意选择一部分空闲的内存块作为存活区。

拷贝的过程称为转移（Evacuation），这和前面的其他年轻代收集器是一样的工作原理。

转移暂停的日志信息很长，为简单起见，我们去除了一些不重要的信息。在并发阶段之后我们会进行详细的讲解。此外，由于日志记录很多，所以并行阶段和“其他”阶段的日志将拆分为多个部分来进行讲解。

我们从 GC 日志中抽取部分关键信息：

2024-06-26T10:53:30.509-0800: [GC pause (G1 Evacuation Pause) (young), 0.0137656 secs]
   [Parallel Time: 11.8 ms, GC Workers: 13]
      // worker 线程的详情
      [GC Worker Start (ms): Min: 388.2, Avg: 388.4, Max: 388.5, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 1.5]
      [Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.2, Sum: 3.5]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 37]
      [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: 10.1, Avg: 10.5, Max: 11.0, Diff: 0.9, Sum: 135.9]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 6.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 11.1, Avg: 11.3, Max: 11.6, Diff: 0.4, Sum: 147.5]
      [GC Worker End (ms): Min: 399.7, Avg: 399.8, Max: 399.9, Diff: 0.2]
   
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 1.7 ms]
      // 其他琐碎任务
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.0 ms]
   
   [Eden: 100.0M(100.0M)->0.0B(87.0M) Survivors: 0.0B->13.0M Heap: 124.0M(200.0M)->45.5M(200.0M)]
 [Times: user=0.03 sys=0.09, real=0.01 secs]

大家一起来分析：

  1. [GC pause (G1 Evacuation Pause) (young), 0.0137656 secs]：G1 转移暂停，纯年轻代模式；只清理年轻代空间，持续的系统时间为 0.0137656 secs 秒，也就是 13.7ms。

  2. [Parallel Time: 11.8 ms, GC Workers: 13]：表明后面的活动由 13 个 Worker 线程并行执行，消耗时间为 11.8 毫秒（real time）；worker 是一种模式，类似于一个老板指挥多个工人干活。

  3. worker 线程的详情：下面再说。

  4. [Code Root Fixup: 0.0 ms]：这一部分通常指的是在垃圾回收过程中对代码根（Code Roots）的修复操作。代码根是指那些直接指向堆中数据（如全局变量、静态变量等）的引用起点。"Fixup"操作可能是为了更新这些引用，确保它们仍然指向正确的内存位置，或者是做些整理工作以帮助垃圾回收更高效地进行。时间戳“0.0 ms”表明这个操作非常快。

  5. [Code Root Purge: 0.0 ms]：代码根的清除（Purge）步骤。这可能涉及到移除不再需要的代码根引用，比如那些不再被任何活跃代码使用的对象引用。这样做有助于释放内存并减少内存泄漏的风险。同样，“0.0 ms”表示该操作未记录到耗时。

  6. [Clear CT: 0.3 ms]：“CT”可能指“Card Table”（卡片表），是垃圾回收中一种常用的数据结构，用于跟踪堆内存中哪些区域被修改过，从而辅助快速识别出需要进行垃圾回收的部分。“Clear CT”操作即清空或重置卡片表，为下一次垃圾回收做准备。时间戳“0.3 ms”标识这个操作耗时0.3毫秒。

  7. [Other: 1.7 ms]：其他活动消耗的时间，其中大部分是并行执行的。

  8. 其他琐碎任务：下面再说。

  9. Eden: 100.0M(100.0M)->0.0B(87.0M)：描述了Eden Space在垃圾回收前后的状态变化。GC前，Eden Space的使用大小是100M，并且其总容量也是100M。经过GC后，Eden Space的使用大小降到了0byte，而Eden Space总容量调整为了87M。这意味着一些空间可能被回收并重新分配给了其他内存区域，或是因为内存管理策略进行了容量调整。

  10. Survivors: 0.0B->13.0M：描述了Survivor Spaces的变化。垃圾回收前幸存者空间没有被使用（0.0B），而回收后，其中一个幸存者空间被分配了13M的空间来存放这次回收后存活的对象。

  11. Heap: 124.0M(200.0M)->45.5M(200.0M)：描述了整个堆内存（Heap）在垃圾回收前后的状况。垃圾回收前，堆的已用空间为124M，总容量为200M。回收之后，堆的已用空间为45.5M，总容量为200M。这表明垃圾回收不仅清理了伊甸园区，也从老年代和其他部分回收了大量不再使用的内存，显著减少了堆的使用量。

  12. [Times: user=0.03 sys=0.09, real=0.01 secs] ：GC 事件的持续时间。

说明：系统时间（wall clock time/elapsed time），是指一段程序从运行到终止，系统时钟走过的时间。一般系统时间都要比 CPU 时间略微长一点。

最繁重的 GC 任务由多个专用的 worker 线程来执行，下面的日志描述了它们的行为：

   [Parallel Time: 11.8 ms, GC Workers: 13]
      // worker 线程的详情
      [GC Worker Start (ms): Min: 388.2, Avg: 388.4, Max: 388.5, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 1.5]
      [Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.2, Sum: 3.5]
         [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 37]
      [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: 10.1, Avg: 10.5, Max: 11.0, Diff: 0.9, Sum: 135.9]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 6.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 11.1, Avg: 11.3, Max: 11.6, Diff: 0.4, Sum: 147.5]
      [GC Worker End (ms): Min: 399.7, Avg: 399.8, Max: 399.9, Diff: 0.2]

Worker 线程的日志信息解读：

  1. [Parallel Time: 11.8 ms, GC Workers: 13]：表明下列活动由 13 个线程并行执行，消耗的时间为 11.8 毫秒（real time）。

  2. GC Worker Start (ms): Min: 388.2, Avg: 388.4, Max: 388.5, Diff: 0.3：[工作线程启动时间（GC Worker Start）]工作线程开始执行垃圾回收的时间范围，表明所有线程几乎同时启动，差异极小。如果 Min 和 Max 差别很大，则表明本机其他进程所使用的线程数量过多，挤占了 GC 的可用 CPU 时间。

  3. Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 1.5：[扩展根扫描（Ext Root Scanning）]扫描堆外内存（non-heap）的 GC ROOT，如 classloaders、JNI 引用、JVM 系统 ROOT 等。后面显示了运行时间，“Sum”指的是 CPU 时间。

  4. [Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.2, Sum: 3.5]:[更新Remembered Set（Update RS）],更新Remembered Set（记录跨代引用的集合）的时间

    • [Processed Buffers: Min: 2, Avg: 2.8, Max: 3, Diff: 1, Sum: 37]:每个工作线程处理的缓冲区数量统计，表明平均每个线程处理了2.8个缓冲区，总和为37个

  5. [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]:[扫描Remembered Set],这一阶段的时间开销极低，可能是因为很少有实际的扫描工作需要做。

  6. [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]：扫描实际代码中的 root 用了多长时间：例如线程栈中的局部变量、静态字段、常量池等

  7. Object Copy (ms): Min: 10.1, Avg: 10.5, Max: 11.0, Diff: 0.9, Sum: 135.9：【对象复制（Object Copy）】，将存活对象从一个区域复制到另一个区域的时间，这是并行GC的一个关键步骤，占用了大部分的并行时间。

  8. Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 6.0：【终止阶段（Termination）】，工作线程完成任务并等待其他线程完成的时间。

    • Termination Attempts: 每个工作线程尝试终止的次数，都只有1次，意味着工作线程很快完成了任务。GC 的 worker 线程尝试多少次 try 和 teminate。如果 worker 发现还有一些任务没处理完，则这一次尝试就是失败的，暂时还不能终止

  9. GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5：【其他工作线程活动（GC Worker Other）】，除了上述具体步骤外，工作线程执行的其他操作的时间。

  10. GC Worker Total (ms): Min: 11.1, Avg: 11.3, Max: 11.6, Diff: 0.4, Sum: 147.5：【工作线程总耗时（GC Worker Total）】，每个工作线程在整个垃圾回收周期内的总工作时间。

  11. GC Worker End (ms): Min: 399.7, Avg: 399.8, Max: 399.9, Diff: 0.2：【工作线程结束时间（GC Worker End）】，工作线程完成垃圾回收任务的时间，表明所有线程几乎同时完成。

此外，在转移暂停期间，还有一些琐碎的小任务。

[Other: 1.7 ms]
  // 其他琐碎任务
  [Choose CSet: 0.0 ms]
  [Ref Proc: 1.0 ms]
  [Ref Enq: 0.0 ms]
  [Redirty Cards: 0.4 ms]
  [Humongous Register: 0.0 ms]
  [Humongous Reclaim: 0.1 ms]
  [Free CSet: 0.0 ms]

其他琐碎任务，这里只介绍其中的一部分：

  1. [Other: 1.7 ms]：其他活动消耗的时间，其中很多是并行执行的。

  2. Choose CSet：选择 CSet 消耗的时间，CSet 是 Collection Set 的缩写。

  3. [Ref Proc: 0.3 ms]：处理非强引用（non-strong）的时间，进行清理或者决定是否需要清理。

  4. [Ref Enq: 0.0 ms]：用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue 中。

  5. Humongous Register、Humongous Reclaim 大对象相关的部分。

  6. [Free CSet: 0.0 ms]：将回收集中被释放的小堆归还所消耗的时间，以便他们能用来分配新的对象。

Concurrent Marking（并发标记）

当堆内存的总体使用比例达到一定数值时，就会触发并发标记。这个默认比例是 45%，但也可以通过 JVM 参数 InitiatingHeapOccupancyPercent 来设置。和 CMS 一样，G1 的并发标记也是由多个阶段组成，其中一些阶段是完全并发的，还有一些阶段则会暂停应用线程。

阶段 1：Initial Mark（初始标记）

可以在 Evacuation Pause 日志中的第一行看到（initial-mark）暂停，类似这样：

2024-06-26T10:53:30.509-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0011710 secs]
  //...
 [Eden: 1024.0K(100.0M)->0.0B(99.0M) Survivors: 0.0B->1024.0K Heap: 153.9M(200.0M)->153.2M(200.0M)]
 
 [Times: user=0.01 sys=0.00, real=0.00 secs]

当然，这里引发 GC 的原因是大对象分配，也可能是其他原因，例如：to-space exhausted，或者默认 GC 原因等等。

to-space exhausted：意味着在垃圾收集过程中，用于存放从源区域（通常是“from-space”）复制过来的活跃对象的“to-space”区域空间已用尽。在G1的垃圾收集算法中，会将存活的对象从当前分配区域移动到新的区域以进行整理和压缩，这一过程称为“疏散”（Evacuation）。当进行这种疏散操作时，如果目标区域（即“to-space”）没有足够的空间来容纳所有需要迁移的活跃对象，就会出现“to-space exhausted”的情况，这时就需要进行额外的操作，比如启动一次混合收集（Mixed GC）来释放更多空间，或者调整策略以提供更多to-space资源，从而继续或完成垃圾收集过程。这种情况反映了内存分配和回收活动的一个瞬间状态，需要垃圾收集算法适当响应以保持应用的正常运行。

to-space并不完全等同于to Survivors

实际上，to-space并不完全等同于to Survivors，尽管它们在概念上有相似之处，都是在垃圾收集过程中作为对象的临时存放区域。

在Java的垃圾收集术语中：

  • Survivor Space 特指在新生代中，用于保存经历过至少一次垃圾回收但依然存活的对象的空间。新生代通常被划分为两个（有时候是三个）相等大小的区域，称为Survivor Space，一个是From Survivor Space（或简称from-space），另一个是To Survivor Space（或简称to-space）。在每次Minor GC后，存活的对象会从from-space复制到to-space，之后from-space可能被清空或部分清空准备下一轮使用，这两个空间的角色会在每次 Minor GC 后互换。

  • To-Space（在G1收集器的上下文中） 更广泛地指代任何在垃圾收集过程中扮演“目标”角色的区域，不只是局限于Survivor Space。在G1中，to-space可以是年轻代内的一个或多个区域，也可以是在混合收集（Mixed GC）期间的老年代区域，用作年轻代对象晋升或老年代内对象的重新分配目标。因此，虽然to-space在某些情境下可能包括或特指To Survivor Space，但它在G1的语境里含义更广，涉及到整个垃圾收集过程中所有作为疏散目标的区域。

总结来说，to-space在更广泛的讨论中是一个更为通用的概念，涵盖了包括但不限于Survivor Space在内的任何用于接收从其他区域搬迁过来的对象的区域。而在具体到Survivor Space的讨论中，to-space则与To Survivor Space紧密相关，是新生代垃圾收集过程的一部分。

阶段 2：Root Region Scan（Root 区扫描）

此阶段标记所有从“根区域”可达的存活对象。

根区域包括：非空的区域，以及在标记过程中不得不收集的区域。

对应的日志：

2024-06-26T10:53:30.509-0800: [GC concurrent-root-region-scan-start]
2024-06-26T10:53:30.509-0800: [GC concurrent-root-region-scan-end, 0.0000854 secs]

阶段 3：Concurrent Mark（并发标记）

对应的日志：

2024-06-26T10:53:30.509-0800: [GC concurrent-mark-start]
2024-06-26T10:53:30.509-0800: [GC concurrent-mark-end, 0.0008582 secs]

阶段 4：Remark（再次标记）

对应的日志：

2024-06-26T10:53:30.509-0800: 
[GC remark 
2024-06-26T10:53:30.509-0800: [Finalize Marking, 0.0003093 secs] 
2024-06-26T10:53:30.509-0800: [GC ref-proc, 0.0001091 secs] 
2024-06-26T10:53:30.509-0800: [Unloading, 0.0005196 secs], 0.0011327 secs]
 [Times: user=0.01 sys=0.01, real=0.00 secs]

1. GC Remark 阶段

  • Finalize Marking: 这是GC的重新标记阶段的一部分，用于完成对存活对象的标记工作，确保所有可达对象都被正确识别。此步骤耗时0.0003093秒。

  • GC ref-proc: 引用处理阶段，负责处理弱引用、软引用和幻象引用，耗时0.0001091秒。这个过程帮助确定哪些弱可达的对象可以被回收。

  • Unloading: 卸载阶段，可能涉及类卸载，即从内存中移除不再使用的类定义，耗时0.0005196秒。

  • 总耗时: 重新标记阶段的整体耗时为0.0011327秒。

2. Remark阶段的时间统计

  • 用户时间(user): 指的是在用户模式下消耗的CPU时间，这里是0.01秒。

  • 系统时间(sys): 在内核模式下消耗的CPU时间，也是0.01秒。

  • 实际时间(real): 实际流逝的时间，这里是0秒，表明GC操作非常高效，几乎不增加额外的延迟。

阶段 5：Cleanup（清理）

最后这个清理阶段为即将到来的转移阶段做准备，统计region中所有存活的对象，并将region进行排序，以提升 GC 的效率。此阶段也为下一次标记执行必需的所有整理工作（house-keeping activities）——维护并发标记的内部状态。

要提醒的是，所有不包含存活对象的region在此阶段都被回收了。有一部分任务是并发的：例如空堆区的回收，还有大部分的存活率计算，此阶段也需要一个短暂的 STW 暂停，才能不受应用线程的影响并完成作业。

这种 STW 停顿的对应的日志如下：

2024-06-26T10:53:30.509-0800: [GC cleanup 100M->100M(200M), 0.0006160 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

GC Cleanup 阶段

  • 时间戳与描述: 记录了GC的清理阶段开始的时间，以及该阶段的具体情况。

  • 100M->100M(200M): 表示清理前后堆的使用量没有变化，仍然是100M，而总的堆大小是200M。这意味着在清理过程中，堆内存占用没有减少也没有增加。

  • 耗时: 清理阶段用了0.0006160秒。

Cleanup阶段的时间统计

  • Times: user=0.00 sys=0.00, real=0.00 secs: 这表明在清理阶段，无论是用户模式还是系统模式，CPU时间消耗都非常小，实际时间也几乎没有增加，再次强调了该阶段的高效性。

如果发现某些region中只包含垃圾，则日志格式可能会有点不同，如：

2024-06-26T10:53:30.509-0800:[GC cleanup 247M->242M(512M)，0.0005349 secs][Times: user=0.00 sys=0.00，real=0.00 secs]
2024-06-26T10:53:30.509-0800:[GC concurrent-cleanup-start]
2024-06-26T10:53:30.509-0800:[GC concurrent-cleanup-end，0.0000134 secs]

如果你在执行示例程序之后没有看到对应的 GC 日志，可以多跑几遍试试。毕竟 GC 和内存分配属于运行时动态的，每次运行都可能有些不同。

综合来看，这段日志描述了G1垃圾收集器在一个特定时刻执行的两个关键步骤：重新标记（remark）和清理（cleanup）。重新标记阶段主要是为了精确识别出所有存活对象，而清理阶段则是在这之后做一些收尾工作，比如更新内部数据结构。整个过程中，尽管进行了复杂的内存管理操作，但对系统性能的影响非常有限，体现了G1收集器在优化应用响应时间和减少停顿时间方面的设计目标。

Evacuation Pause（mixed）（转移暂停：混合模式）

并发标记完成之后，G1 将执行一次混合收集（mixed collection），不只清理年轻代，还将一部分老年代区域也加入到 collection set 中。混合模式的转移暂停（Evacuation Pause）不一定紧跟并发标记阶段。在并发标记与混合转移暂停之间，很可能会存在多次 Young 模式的转移暂停。“混合模式”就是指这次 GC 事件混合着处理年轻代和老年代的 region。这也是 G1 等增量垃圾收集器的特色。

  1. 在并发标记（Concurrent Marking）完成后，G1确实会规划一次混合收集（Mixed Collection），这个过程不仅清理年轻代，还会选择一部分老年代的区域一并回收，这些被选中的区域会被添加到收集集合（Collection Set）中准备回收。

  2. 混合收集的 Evacuation Pause（转移暂停）并不直接紧接着并发标记阶段发生，两者之间可以有时间间隔，并且可能间插有多次仅针对年轻代的Evacuation Pause，用以维持年轻代的空间需求。

  3. “混合模式”恰如其分地概括了这种同时涉及年轻代和老年代回收的GC行为，是G1作为增量式（incremental）或说是分代并发垃圾收集器的一大特色，体现了其在减少停顿时间和提高整体系统吞吐量上的设计意图。

混合模式下的日志，和纯年轻代模式相比，可以发现一些有趣的地方：

2024-06-26T10:53:30.509-0800: 
//一次因“G1 Humongous Allocation”（尝试分配巨型对象）导致的空间不足而触发的混合GC（mixed GC）暂停，持续时间为 0.0010838 秒
[GC pause (G1 Humongous Allocation) (mixed) (to-space exhausted), 0.0010838 secs]
    //并行时间: 总共用了 0.4 毫秒的并行时间，涉及 13 个GC工作线程
   [Parallel Time: 0.4 ms, GC Workers: 13]
      // GC 工作线程（GC Workers）的活动细节
      [GC Worker Start (ms): Min: 597.7, Avg: 597.8, Max: 597.9, Diff: 0.2]
      // 工作线程详情
      //扩展根扫描耗时，涉及JVM外部的根对象（比如JNI引用）
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      // 递增更新Remembered Sets（记录跨代引用的结构）的耗时
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
         //处理的缓冲区数量	
         [Processed Buffers: Min: 0, Avg: 1.5, Max: 2, Diff: 2, Sum: 19]
      //扫描Remembered Sets的耗时，此处全部为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: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      // 工作线程完成任务并准备终止的等待和处理时间
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         // 每个工作线程尝试终止的次数
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      // 工作线程执行其他非特定任务的时间
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      //  每个工作线程执行GC总耗时
      [GC Worker Total (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 2.7]
      // 工作线程结束执行的时间范围
      [GC Worker End (ms): Min: 598.0, Avg: 598.0, Max: 598.0, Diff: 0.0]

   //修正和清除代码根的耗时   
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   //清除Card Table（记录堆内存变动）的耗时
   [Clear CT: 0.1 ms]
   //Other 部分列出了其他辅助操作的时间，
   //包括Evacuation Failure（疏散失败）、Choose CSet（选择回收集）、
   //Ref Proc/Enq（引用处理和入队）、Redirty Cards（重新标记脏卡）、
   //Humongous Register/Reclaim（巨型对象注册和回收）、Free CSet（释放回收集）
   [Other: 0.6 ms]
      [Evacuation Failure: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   
   // Eden: 显示了年轻代Eden区从 2048K 清空至 0B，Eden区总大小仍为 100M，Survivor空间未变。
   // Heap: 堆内存使用量从 156.4M 减少到 155.8M，总堆大小为 200M。
   [Eden: 2048.0K(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 156.4M(200.0M)->155.8M(200.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

  1. [Clear CT: 0.1 ms]：清理 card table 中 cards 的时间。清理工作只是简单地删除“脏”状态，此状态用来标识一个字段是否被更新的，供 Remembered Sets 使用。

  2. [Redirty Cards: 0.1 ms]：将 card table 中适当的位置标记为 dirty 所花费的时间。“适当的位置”是由 GC 本身执行的堆内存改变所决定的，例如引用排队等。

Full GC（Allocation Failure）

G1 是一款自适应的增量垃圾收集器。一般来说，只有在内存严重不足的情况下才会发生 Full GC。比如堆空间不足或者 to-space 空间不足。

在前面的示例程序基础上，增加缓存对象的数量，即可模拟 Full GC。

示例日志如下：

2024-06-26T10:53:30.819-0800:
[Full GC (Allocation Failure)  164M->125M(200M), 0.0123424 secs]
   [Eden: 0.0B(100.0M)->0.0B(100.0M) Survivors: 0.0B->0.0B Heap: 164.3M(200.0M)->125.7M(200.0M)], [Metaspace: 2966K->2966K(1056768K)]
 [Times: user=0.01 sys=0.00, real=0.02 secs]

因为堆内存空间很小，存活对象的数量也不多，所以这里看到的 Full GC 暂停时间很短。

在堆内存较大的情况下（8G+），如果 G1 发生了 Full GC，暂停时间可能会退化，达到几十秒甚至更多。如下面这张图片所示：

详细解读 GC 日志

从其中的 OldGen 部分可以看到，118 次 Full GC 消耗了 31 分钟，平均每次达到 20 秒，按图像比例可粗略得知，吞吐率不足 30%。

这张图片所表示的场景是在压测 Flink 按时间窗口进行聚合计算时发生的，主要原因是对象太多，堆内存空间不足而导致的，修改对象类型为原生数据类型之后问题得到缓解，加大堆内存空间，满足批处理/流计算的需求之后 GC 问题不再复现。

发生持续时间很长的 Full GC 暂停时，就需要我们进行排查和分析，确定是否需要修改 GC 配置，或者增加内存，还是需要修改程序的业务逻辑。关于 G1 的调优，我们在后面的调优部分再进行介绍。

上一个 IOS 实现轻松更换 App 图标...
下一个 在 Go 中如何检查结构体是否为空

相关推荐

0条评论

您的电子邮件等信息不会被公开，以下所有项均必填

OK! You can skip this field.