投稿
  1. 极客之音首页
  2. 技术漫谈

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

小半 • • 技术漫谈 • 阅读 469

1.前言

哈哈，有点标题党的感觉，只是想强调下重要性，手动狗头保命~

JVM（Java虚拟机）的垃圾回收（GC）机制是Java应用程序运行时内存管理的重要组成部分。通过分析JVM GC日志，我们可以了解和优化应用程序的性能和内存使用情况。本文将介绍JVM GC日志的基本原理和常见的分析技巧，以帮助开发人员更好地理解垃圾回收过程、定位性能问题并采取相应的优化措施。

GC日志的配置和分析门槛相对来说有点高，至少需要对JVM有比较深入的了解的开发同学才能去做。一般在应用程序突然响应变慢、吞吐量降低但进程又没有僵死这种问题出现时，就需要借助JVM GC日志来协助排查问题。

以下是JVM的储备知识，可点击跳转阅读。

本文如无特别说明，默认的JDK版本是8，JVM虚拟机是64位的HotSpot。

2.为什么需要分析GC日志

  • • 理解GC行为：GC日志提供了垃圾回收器的详细信息，包括GC类型、停顿时间、回收的对象数量等，帮助我们了解垃圾回收器的工作原理和行为。

  • • 优化GC性能：通过分析GC日志，我们可以发现GC瓶颈，识别内存泄漏和过度分配等问题，并采取相应的优化措施，提高应用程序的性能和稳定性。

  • • 调整GC参数：GC日志中记录了垃圾回收器的各种参数和标记，通过分析日志，我们可以了解当前的GC配置是否合适，是否需要调整GC参数。

    3.分析GC日志的方法

  • • GC类型分析：通过识别GC日志中的GC类型，如Minor GC、Major GC或Full GC，可以了解垃圾回收器的行为和触发条件。如果应用程序经常触发整堆收集，可能需要增加老年代的大小或调整垃圾回收器的参数。

  • • 停顿时间分析：GC日志中记录了GC的停顿时间，可以分析GC的停顿时间分布和频率，找出长时间停顿的原因，以及是否需要调整垃圾回收器的参数。通过查看GC期间应用程序的CPU使用率和堆内存使用情况，如果应用程序在GC期间使用大量CPU和堆内存，可能需要调整垃圾回收器的参数或增加堆内存大小

  • • 内存使用分析：GC日志中包含了堆内存的使用情况，可以分析堆内存的分配和释放情况，判断是否存在内存泄漏或过度分配的问题。如果应用程序产生大量短生命周期的对象，可能需要调整新生代的大小和垃圾回收器的参数。

  • • GC参数调优：通过分析GC日志中的GC标记和参数，可以判断当前的GC配置是否合理，如果应用程序经常触发某种特定的垃圾回收操作，可能需要调整垃圾回收器的参数。

    4.GC日志的生成和格式

    4 4.1生成GC日志

    在启动Java应用程序的命令中，我们可以通过添加相关GC日志参数来生成GC日志，主要常用的参数如下：

  • • -XX:+PrintGCDetails：用于在GC发生时打印详细的GC日志信息（一般在JVM退出前会打印堆内存信息）。

  • • -XX:+PrintGCDateStamps：用于在GC发生时打印GC日志信息的日期和时间戳（常用，显示具体时间到毫秒，比如：2023-08-31T11:36:54.306+0800）

  • • -XX:+PrintGCTimeStamps：用于在GC发生时打印GC日志信息的时间戳（一般不会配置这个参数，看不到具体发生GC的时间，日志开头是这样的时间戳：0.317）

  • • -XX:+PrintHeapAtGC：用于在GC发生时打印Java堆内存的详细信息（每一次发生GC前后都打印堆内存信息，一般不用配置，因为配这个参数后日志文件会很大，通常根据-XX:+PrintGCDetails里GC的详细信息能知道堆内存占用情况）

  • • -Xloggc：配置gc日志存放的位置，支持使用 %p ， %t 等占位符来指定GC输出文件。%p表示进程pid，%t表示启动时间戳。例如: -Xloggc:D:/gc/gc-%p-%t.log。（注意除文件名外路径一定要先存在，不然会报错导致日志写不到文件里）

  • • -XX:+UseGCLogFileRotation：启用GC日志文件滚动存放的，避免一个日志文件过大，通常配合-XX:NumberOfGCLogFiles，-XX:GCLogFileSize这两个参数使用。

  • • -XX:NumberOfGCLogFiles：指定GC文件数量，必须大于0

  • • -XX:GCLogFileSize：指定每个GC日志文件的大小，最小是8k。

  • • -XX:+UseAdaptiveSizePolicy：作用是启用JVM的自适应大小策略（只设置总内存大小，其他参数比如你年轻代老年代大小占比，Eden区与Survivor区占比等这些由JVM自适应调整）。该策略可以根据当前可用内存和正在运行的应用程序的需求自动调整堆的大小，默认是开启的，可根据实际情况选择是否关闭。

一个完整的打印GC日志的命令参数：

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m GcTest

这行命令会把GC日志存放到D:/gc/gcfile目录下，日志文件滚动存储，每个最大10m，共可存5个文件，文件名用进程id和时间戳表示。

测试GC输出例子（可以用java命令行执行class，也可以在IDEA工具添加VM参数）：

public class GcTest {

    public static void main(String[] args) throws Exception {
        List<User> list = new ArrayList<>();
        while (true) {
            list.add(new User());
        }
    }
}

class User {
    private String name;
    private int age;
    private byte[] data = new byte[1024 * 1024];
}

执行后会生成GC文件：

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

文件内容：

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

4.2GC日志格式

除以上配置GC日志相关参数外，还可以配置JVM内存大小、垃圾收集器等参数，不同的垃圾收集器JVM日志内容也有差异，这里统一将堆的大小设置为256m，除垃圾收集器参数外其余都默认，下面我们逐个解释。

常见日志格式有以下两种：

  • • GC (Allocation Failure)：

指年轻代中没有足够的空间能够存储新的数据而导致的垃圾回收。

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

  • • Full GC (Allocation Failure)

指年轻代、老年代、永久代（元空间）的全体内存空间的垃圾回收。

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

4.2.1-XX:+UseSerialGC

指定年轻代和老年代都使用串行垃圾收集器，Serial GC（年轻代）+Serial Old GC（老年代）。命令：

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseSerialGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

最终运行结果如下：

Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at User.<init>(GcTest.java:27)
        at GcTest.main(GcTest.java:19)

我们也可以通过JDK自带的jvisualvm来观察GC及堆的使用情况。

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

GC日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(3746312k free), swap 33385592k(9419488k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC 
2023-09-03T10:45:23.975+0800: 0.062: [GC (Allocation Failure) 2023-09-03T10:45:23.975+0800: 0.062: [DefNew: 7292K->629K(9216K), 0.0029085 secs] 7292K->6773K(29696K), 0.0030178 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2023-09-03T10:45:23.978+0800: 0.065: [GC (Allocation Failure) 2023-09-03T10:45:23.978+0800: 0.065: [DefNew: 7957K->0K(9216K), 0.0024333 secs] 14101K->13940K(29696K), 0.0024575 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T10:45:23.981+0800: 0.068: [GC (Allocation Failure) 2023-09-03T10:45:23.981+0800: 0.068: [DefNew: 7320K->7320K(9216K), 0.0000073 secs]2023-09-03T10:45:23.981+0800: 0.068: [Tenured: 13940K->20084K(20480K), 0.0030373 secs] 21261K->21108K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0030776 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T10:45:23.984+0800: 0.072: [Full GC (Allocation Failure) 2023-09-03T10:45:23.984+0800: 0.072: [Tenured: 20084K->20084K(20480K), 0.0013057 secs] 27408K->27253K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0013293 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T10:45:23.986+0800: 0.073: [Full GC (Allocation Failure) 2023-09-03T10:45:23.986+0800: 0.073: [Tenured: 20084K->20071K(20480K), 0.0022037 secs] 27253K->27240K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0022199 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 7481K [0x00000000fe200000, 0x00000000fec00000, 0x00000000fec00000)
  eden space 8192K,  91% used [0x00000000fe200000, 0x00000000fe94e738, 0x00000000fea00000)
  from space 1024K,   0% used [0x00000000fea00000, 0x00000000fea00000, 0x00000000feb00000)
  to   space 1024K,   0% used [0x00000000feb00000, 0x00000000feb00000, 0x00000000fec00000)
 tenured generation   total 20480K, used 20071K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
   the space 20480K,  98% used [0x00000000fec00000, 0x00000000fff99e68, 0x00000000fff9a000, 0x0000000100000000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

第一行：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)

这是打印JVM版本信息。第二行：

Memory: 4k page, physical 16608376k(3527692k free), swap 33385592k(9535508k free)

这是操作系统内存信息，页大小是4k，physical表示物理内存，16608376k约等于16G，这是总物理内存大小，3527692k是可用内存大小，约等于3.4G，swap表示交换区空间，33385592k约等于32G，这是总交换区大小，9535508k是可用交换区大小，约等于9.1G。

为什么交换区空间比物理内存还大呢?
这是因为Swap交换区空间是操作系统为了缓解物理内存不足而在磁盘上分配的一部分空间，用于将内存中不常用的数据交换到磁盘上，以便为其他更需要内存的进程腾出空间。在Linux系统中，交换区空间通常被称为交换空间（Swap Space）。通常情况下，交换空间的大小会比物理内存大，因为交换空间是为了缓解物理内存不足而设计的，而物理内存的大小受限于计算机硬件的限制，通常无法达到磁盘空间的大小。因此，为了确保系统在需要时能够有足够的空间进行交换操作，交换空间的大小通常会设置得比物理内存大一些。

第三行：

CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC

主要是打印JVM命令参数信息，方便了解JVM配置。

-XX:GCLogFileSize=10485760表示GC日志文件大小是10485760b等于10m
-XX:InitialHeapSize=31457280表示堆内存初始大小是31457280b等于30m
-XX:MaxHeapSize=31457280表示堆内存最大可占用大小是31457280b等于30m
-XX:NumberOfGCLogFiles=5表示日志文件个数为5，因为是滚动存储的
-XX:+PrintGC打印垃圾回收信息
-XX:+PrintGCDateStamps打印垃圾回收时间
-XX:+PrintGCDetails打印垃圾收集详细信息
-XX:+PrintGCTimeStamps打印垃圾回收时间戳
-XX:+UseCompressedClassPointers启用类指针压缩（JDK8默认开启）
-XX:+UseCompressedOops启用普通指针压缩（JDK8默认开启）
-XX:+UseGCLogFileRotation启用GC日志文件滚动存放
-XX:-UseLargePagesIndividualAllocation 禁用大页分配
-XX:+UseSerialGC 指定垃圾收集器使用Serial GC（年轻代）+Serial Old GC（老年代）

第四行：

2023-09-03T10:45:23.975+0800: 0.062: [GC (Allocation Failure) 2023-09-03T10:45:23.975+0800: 0.062: [DefNew: 7292K->629K(9216K), 0.0029085 secs] 7292K->6773K(29696K), 0.0030178 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

这就是基本的GC日志信息了。

  • • 2023-09-03T10:45:23.975+0800: 0.062：打印GC发生的时间，0.062表示自JVM启动到发生GC的秒数。

  • • GC (Allocation Failure)：表示GC类型和原因，Allocation Failure表示分配空间失败。

  • • DefNew: 7292K->629K(9216K), 0.0029085 secs：表示GC发生的区域，DefNew（Default New Generation）表示serial垃圾收集器工作在年轻代区域，7292K表示GC发生前年轻代占用空间大小，629K表示GC发生后年轻代占用空间大小，(9216K)表示年轻代占用空间大小，等于9m（我们推算一下，因为配置的堆内存大小是30m，按默认的年轻代：老年代=1:2，所以年轻代总大小是30 * 1 / 3 = 10m，年轻代Eden区：Survivor From区:Survivor To区=8:1:1，年轻代实际使用空间=Eden区+一个Survivor区，占比就是(8+1)/(8+1+1)=0.9，所以实际占用大概10*0.9等于9m），0.0214271 secs表示执行垃圾回收耗时。

  • • 7292K->6773K(29696K)：7292K表示GC前整个堆空间大小， 6773K表示GC后堆空间总大小，29696K表示堆空间总大小（等于总堆大小减去其中一个空闲Survivor区域，29696K=29m）。

  • • 0.0030178 secs：表示GC垃圾回收耗时。

  • • Times: user=0.02 sys=0.00, real=0.00 secs：user表示用户态耗时，sys表示内核态耗时，real表示实际耗时。

第六行：

2023-09-03T10:45:23.981+0800: 0.068: [GC (Allocation Failure) 2023-09-03T10:45:23.981+0800: 0.068: [DefNew: 7320K->7320K(9216K), 0.0000073 secs]2023-09-03T10:45:23.981+0800: 0.068: [Tenured: 13940K->20084K(20480K), 0.0030373 secs] 21261K->21108K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0030776 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

这一次的GC可以了解到，由于新分配的对象占用空间大概是1m多，Eden+Survivor之一已经占用7m多了，年轻代可能已经无法满足新对象空间分配了，所以新对象直接在老年代分配空间。

  • • DefNew: 7320K->7320K(9216K)，年轻代没有变化。

  • • Tenured代表老年代，Tenured: 13940K->20084K(20480K), 0.0030373 secs，老年代在GC前占用13940K，GC后占用20084K，说明GC后老年代占用空间增加了，20480K表示老年代占用20m的空间，说明年轻代没有空间给新对象分配，对象直接进入老年代分配了

  • • Metaspace: 2618K->2618K(1056768K)：元空间GC前后没有发生变化，元空间占用的是系统内存，这个内存大小会根据实际情况动态调整。

第七行：

2023-09-03T10:45:23.984+0800: 0.072: [Full GC (Allocation Failure) 2023-09-03T10:45:23.984+0800: 0.072: [Tenured: 20084K->20084K(20480K), 0.0013057 secs] 27408K->27253K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0013293 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

这一次GC跟前面的就有区别了，发生了Full GC。

  • • Full GC (Allocation Failure) ：GC类型是Full GC，发生GC的原因还是内存分配失败。

  • • Tenured: 20084K->20084K(20480K), 0.0013057 secs，通过老年代GC前后内存占用空间没变，没有回收掉垃圾对象，这样年轻代满了，老年代也满了，就可能要发生内存溢出了

第九行：

Heap
 def new generation   total 9216K, used 7481K [0x00000000fe200000, 0x00000000fec00000, 0x00000000fec00000)
  eden space 8192K,  91% used [0x00000000fe200000, 0x00000000fe94e738, 0x00000000fea00000)
  from space 1024K,   0% used [0x00000000fea00000, 0x00000000fea00000, 0x00000000feb00000)
  to   space 1024K,   0% used [0x00000000feb00000, 0x00000000feb00000, 0x00000000fec00000)
 tenured generation   total 20480K, used 20071K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
   the space 20480K,  98% used [0x00000000fec00000, 0x00000000fff99e68, 0x00000000fff9a000, 0x0000000100000000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

这一行是在JVM退出前打印的堆内存信息。

  • • def new generation表示serial串行收集器时的年轻代，total 9216K等于9m（Eden区加一个Survivor区的大小，另一个Survivor留给复制备用），eden space 8192K等于8m，from space和to space各1024K等于1m，符合8:1:1分配规则。

  • • tenured generation total 20480K等于20m表示老年代占用空间大小，年轻代和老年代也满足1:2分配规则。

  • • Metaspace used 2651K, capacity 4486K, committed 4864K, reserved 1056768K，这个是元空间，把元空间已使用大小，容量和保留空间大小都给列出来了。

  • • 0x00000000fe200000这些16进制表示的是内存地址。

接下来的几种垃圾收集器重点关注特有点，其他共同的地方不再详细描述。

4.2.2-XX:+UseConcMarkSweepGC -XX:-UseParNewGC

老年代使用CMS收集器，年轻代使用Serial收集器，Serial GC（年轻代）+CMS GC（老年代）

这个组合在JDK8中声明废弃了（但是还可以用），从JDK9完全移除了，不再使用这个组合。而CMS收集器在JDK14版本被移除了

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:-UseParNewGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC日志：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(4383588k free), swap 33385592k(9325000k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:-UseParNewGC 
2023-09-03T14:36:59.325+0800: 0.100: [GC (Allocation Failure) 2023-09-03T14:36:59.325+0800: 0.100: [DefNew: 7292K->629K(9216K), 0.0029281 secs] 7292K->6775K(29696K), 0.0030213 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.329+0800: 0.104: [GC (Allocation Failure) 2023-09-03T14:36:59.329+0800: 0.104: [DefNew: 7957K->0K(9216K), 0.0033945 secs] 14104K->13946K(29696K), 0.0034220 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.344+0800: 0.118: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13946K(20480K)] 16147K(29696K), 0.0001306 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.344+0800: 0.119: [CMS-concurrent-mark-start]
2023-09-03T14:36:59.345+0800: 0.119: [GC (Allocation Failure) 2023-09-03T14:36:59.345+0800: 0.119: [DefNew: 7320K->7320K(9216K), 0.0000128 secs]2023-09-03T14:36:59.345+0800: 0.119: [CMS2023-09-03T14:36:59.345+0800: 0.120: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 13946K->20087K(20480K), 0.0051708 secs] 21267K->21112K(29696K), [Metaspace: 2619K->2619K(1056768K)], 0.0052267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.350+0800: 0.125: [Full GC (Allocation Failure) 2023-09-03T14:36:59.350+0800: 0.125: [CMS: 20087K->20087K(20480K), 0.0017017 secs] 27411K->27256K(29696K), [Metaspace: 2619K->2619K(1056768K)], 0.0017281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.352+0800: 0.126: [Full GC (Allocation Failure) 2023-09-03T14:36:59.352+0800: 0.126: [CMS: 20087K->20075K(20480K), 0.0023832 secs] 27256K->27244K(29696K), [Metaspace: 2619K->2619K(1056768K)], 0.0024020 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.354+0800: 0.129: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20075K(20480K)] 27393K(29696K), 0.0001098 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.355+0800: 0.129: [CMS-concurrent-mark-start]
2023-09-03T14:36:59.355+0800: 0.130: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.355+0800: 0.130: [CMS-concurrent-preclean-start]
2023-09-03T14:36:59.355+0800: 0.130: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.355+0800: 0.130: [CMS-concurrent-abortable-preclean-start]
2023-09-03T14:36:59.355+0800: 0.130: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.356+0800: 0.130: [GC (CMS Final Remark) [YG occupancy: 7317 K (9216 K)]2023-09-03T14:36:59.356+0800: 0.130: [Rescan (non-parallel) 2023-09-03T14:36:59.356+0800: 0.130: [grey object rescan, 0.0000521 secs]2023-09-03T14:36:59.356+0800: 0.130: [root rescan, 0.0001052 secs]2023-09-03T14:36:59.356+0800: 0.130: [visit unhandled CLDs, 0.0000041 secs]2023-09-03T14:36:59.356+0800: 0.130: [dirty klass scan, 0.0000102 secs], 0.0001906 secs]2023-09-03T14:36:59.356+0800: 0.130: [weak refs processing, 0.0000057 secs]2023-09-03T14:36:59.356+0800: 0.130: [class unloading, 0.0000950 secs]2023-09-03T14:36:59.356+0800: 0.130: [scrub symbol table, 0.0001736 secs]2023-09-03T14:36:59.356+0800: 0.131: [scrub string table, 0.0000766 secs][1 CMS-remark: 20075K(20480K)] 27393K(29696K), 0.0005813 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.356+0800: 0.131: [CMS-concurrent-sweep-start]
2023-09-03T14:36:59.356+0800: 0.131: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:36:59.356+0800: 0.131: [CMS-concurrent-reset-start]
2023-09-03T14:36:59.356+0800: 0.131: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 7481K [0x00000000fe200000, 0x00000000fec00000, 0x00000000fec00000)
  eden space 8192K,  91% used [0x00000000fe200000, 0x00000000fe94e738, 0x00000000fea00000)
  from space 1024K,   0% used [0x00000000fea00000, 0x00000000fea00000, 0x00000000feb00000)
  to   space 1024K,   0% used [0x00000000feb00000, 0x00000000feb00000, 0x00000000fec00000)
 concurrent mark-sweep generation total 20480K, used 20074K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

年轻代还是使用DefNew表示，说明使用的就是serial串行垃圾收集器。然后还可以看到GC (CMS Initial Mark)，CMS-concurrent-xxx的标记，这正是CMS收集器产生的日志，我们在后面使用-XX:+UseConcMarkSweepGC时一并介绍CMS日志。

4.2.3-XX:+UseParNewGC

年轻代使用ParNew收集器，老年代使用串行收集器，ParNewGC（年轻代）+Serial Old GC（老年代）

这个组合在JDK8中声明废弃了（但是还可以用），从JDK9完全移除了，不再使用这个组合

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseParNewGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(4154900k free), swap 33385592k(9238332k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2023-09-03T15:00:02.429+0800: 0.082: [GC (Allocation Failure) 2023-09-03T15:00:02.429+0800: 0.082: [ParNew: 7292K->661K(9216K), 0.0044641 secs] 7292K->6806K(29696K), 0.0045585 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2023-09-03T15:00:02.434+0800: 0.087: [GC (Allocation Failure) 2023-09-03T15:00:02.434+0800: 0.087: [ParNew: 7990K->170K(9216K), 0.0012816 secs] 14134K->14140K(29696K), 0.0013034 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:00:02.436+0800: 0.089: [GC (Allocation Failure) 2023-09-03T15:00:02.436+0800: 0.089: [ParNew: 7491K->7491K(9216K), 0.0000074 secs]2023-09-03T15:00:02.436+0800: 0.089: [Tenured: 13969K->20113K(20480K), 0.0030046 secs] 21460K->21137K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0030388 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:00:02.439+0800: 0.092: [Full GC (Allocation Failure) 2023-09-03T15:00:02.439+0800: 0.092: [Tenured: 20113K->20113K(20480K), 0.0012265 secs] 27437K->27282K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0012493 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:00:02.440+0800: 0.093: [Full GC (Allocation Failure) 2023-09-03T15:00:02.440+0800: 0.093: [Tenured: 20113K->20071K(20480K), 0.0023807 secs] 27282K->27240K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0023973 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 7481K [0x00000000fe200000, 0x00000000fec00000, 0x00000000fec00000)
  eden space 8192K,  91% used [0x00000000fe200000, 0x00000000fe94e738, 0x00000000fea00000)
  from space 1024K,   0% used [0x00000000fea00000, 0x00000000fea00000, 0x00000000feb00000)
  to   space 1024K,   0% used [0x00000000feb00000, 0x00000000feb00000, 0x00000000fec00000)
 tenured generation   total 20480K, used 20071K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
   the space 20480K,  98% used [0x00000000fec00000, 0x00000000fff99e68, 0x00000000fff9a000, 0x0000000100000000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

  • • [ParNew: 7292K->661K(9216K), 0.0044641 secs]，ParNew是“Parallel New Generation”的简写，表示年轻代使用的是ParNew收集器。

  • • [Tenured: 13969K->20113K(20480K), 0.0030046 secs]，Tenured表示老年代使用的是serial old串行收集器。

4.2.4-XX:+UseConcMarkSweepGC

年轻代使用ParNew收集器，老年代使用CMS收集器，ParNewGC（年轻代）+CMS GC（老年代），也可以使用这个组合：-XX:+UseConcMarkSweepGC -XX:+UseParNewGC效果是一样的，另外CMS收集器在调优上还有许多其他参数配合使用，详细的参数可参考之前的文章。

CMS收集器在JDK14版本被移除了

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(4317328k free), swap 33385592k(9205688k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2023-09-03T15:08:04.321+0800: 0.061: [GC (Allocation Failure) 2023-09-03T15:08:04.321+0800: 0.062: [ParNew: 7292K->658K(9216K), 0.0010200 secs] 7292K->6815K(29696K), 0.0011644 secs] [Times: user=0.03 sys=0.06, real=0.00 secs] 
2023-09-03T15:08:04.322+0800: 0.063: [GC (Allocation Failure) 2023-09-03T15:08:04.322+0800: 0.063: [ParNew: 7987K->114K(9216K), 0.0026833 secs] 14143K->14075K(29696K), 0.0027130 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.325+0800: 0.066: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13960K(20480K)] 16276K(29696K), 0.0004940 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.325+0800: 0.067: [CMS-concurrent-mark-start]
2023-09-03T15:08:04.326+0800: 0.067: [GC (Allocation Failure) 2023-09-03T15:08:04.326+0800: 0.067: [ParNew: 7435K->7435K(9216K), 0.0000092 secs]2023-09-03T15:08:04.326+0800: 0.067: [CMS2023-09-03T15:08:04.337+0800: 0.078: [CMS-concurrent-mark: 0.001/0.011 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
 (concurrent mode failure): 13960K->20087K(20480K), 0.0154906 secs] 21396K->21112K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0155419 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2023-09-03T15:08:04.341+0800: 0.083: [Full GC (Allocation Failure) 2023-09-03T15:08:04.341+0800: 0.083: [CMS: 20087K->20087K(20480K), 0.0018232 secs] 27411K->27256K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0018535 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.343+0800: 0.085: [Full GC (Allocation Failure) 2023-09-03T15:08:04.343+0800: 0.085: [CMS: 20087K->20075K(20480K), 0.0024655 secs] 27256K->27244K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0024877 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.346+0800: 0.088: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20075K(20480K)] 27393K(29696K), 0.0006451 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.088: [CMS-concurrent-mark-start]
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-preclean-start]
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-abortable-preclean-start]
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.348+0800: 0.089: [GC (CMS Final Remark) [YG occupancy: 7317 K (9216 K)]2023-09-03T15:08:04.348+0800: 0.089: [Rescan (parallel) , 0.0005214 secs]2023-09-03T15:08:04.348+0800: 0.090: [weak refs processing, 0.0000120 secs]2023-09-03T15:08:04.348+0800: 0.090: [class unloading, 0.0001100 secs]2023-09-03T15:08:04.348+0800: 0.090: [scrub symbol table, 0.0001853 secs]2023-09-03T15:08:04.348+0800: 0.090: [scrub string table, 0.0000828 secs][1 CMS-remark: 20075K(20480K)] 27393K(29696K), 0.0009780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-sweep-start]
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-reset-start]
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 7481K [0x00000000fe200000, 0x00000000fec00000, 0x00000000fec00000)
  eden space 8192K,  91% used [0x00000000fe200000, 0x00000000fe94e738, 0x00000000fea00000)
  from space 1024K,   0% used [0x00000000fea00000, 0x00000000fea00000, 0x00000000feb00000)
  to   space 1024K,   0% used [0x00000000feb00000, 0x00000000feb00000, 0x00000000fec00000)
 concurrent mark-sweep generation total 20480K, used 20074K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

ParNew: 7292K->658K(9216K), 0.0010200 secs，通过这个ParNew可以看到年轻代使用的正是ParNew收集器。通过日志我们可以看到一个完整的CMS过程，重点关注下CMS收集器的执行过程及解释如下：

// (CMS Initial Mark)CMS初始标记，会发生STW
2023-09-03T15:08:04.346+0800: 0.088: [GC (CMS Initial Mark) [1 CMS-initial-mark: 20075K(20480K)] 27393K(29696K), 0.0006451 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.088: [CMS-concurrent-mark-start]
// (CMS-concurrent-mark)CMS并发标记，可用户线程并发执行
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-preclean-start]
// (CMS-concurrent-preclean)对前一个阶段标记了又发生改变的对象标记
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-abortable-preclean-start]
// (CMS-concurrent-abortable-preclean)可终止的并发预清理
2023-09-03T15:08:04.347+0800: 0.089: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
// (CMS Final Remark)CMS最终标记,会发生STW
2023-09-03T15:08:04.348+0800: 0.089: [GC (CMS Final Remark) [YG occupancy: 7317 K (9216 K)]2023-09-03T15:08:04.348+0800: 0.089: [Rescan (parallel) , 0.0005214 secs]2023-09-03T15:08:04.348+0800: 0.090: [weak refs processing, 0.0000120 secs]2023-09-03T15:08:04.348+0800: 0.090: [class unloading, 0.0001100 secs]2023-09-03T15:08:04.348+0800: 0.090: [scrub symbol table, 0.0001853 secs]2023-09-03T15:08:04.348+0800: 0.090: [scrub string table, 0.0000828 secs][1 CMS-remark: 20075K(20480K)] 27393K(29696K), 0.0009780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-sweep-start]
// (CMS-concurrent-sweep)CMS并发清除
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-reset-start]
// (CMS-concurrent-reset)重置本次GC过程标记的数据，为下一个CMS做准备
2023-09-03T15:08:04.349+0800: 0.090: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

4.2.5-XX:+UseParallelGC -XX:-UseParallelOldGC

年轻代使用Parallel Scavenge收集器，老年代使用Serial Old收集器，Parallel Scavenge GC（年轻代）+Serial Old GC（老年代）。

这个组合在JDK14中被移除了。

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseParallelGC -XX:-UseParallelOldGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC产生日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(4442632k free), swap 33385592k(9116504k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC -XX:-UseParallelOldGC 
2023-09-03T15:24:24.273+0800: 0.075: [GC (Allocation Failure) [PSYoungGen: 8152K->848K(9216K)] 8152K->8024K(29696K), 0.0015640 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:24:24.275+0800: 0.077: [GC (Allocation Failure) [PSYoungGen: 8178K->888K(9216K)] 15354K->15232K(29696K), 0.0011565 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:24:24.276+0800: 0.078: [Full GC (Ergonomics) [PSYoungGen: 888K->0K(9216K)] [PSOldGen: 14344K->14970K(20480K)] 15232K->14970K(29696K), [Metaspace: 2615K->2615K(1056768K)], 0.0206906 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2023-09-03T15:24:24.298+0800: 0.100: [Full GC (Ergonomics) [PSYoungGen: 7321K->2048K(9216K)] [PSOldGen: 14970K->20090K(20480K)] 22292K->22138K(29696K), [Metaspace: 2615K->2615K(1056768K)], 0.0024213 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:24:24.300+0800: 0.102: [Full GC (Ergonomics) [PSYoungGen: 7316K->7316K(9216K)] [PSOldGen: 20090K->20090K(20480K)] 27406K->27406K(29696K), [Metaspace: 2615K->2615K(1056768K)], 0.0008093 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:24:24.301+0800: 0.103: [Full GC (Allocation Failure) [PSYoungGen: 7316K->7168K(9216K)] [PSOldGen: 20090K->20071K(20480K)] 27406K->27240K(29696K), [Metaspace: 2615K->2615K(1056768K)], 0.0031371 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 7468K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 91% used [0x00000000ff600000,0x00000000ffd4b3e8,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
  to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
 PSOldGen        total 20480K, used 20071K [0x00000000fe200000, 0x00000000ff600000, 0x00000000ff600000)
  object space 20480K, 98% used [0x00000000fe200000,0x00000000ff599ef8,0x00000000ff600000)
 Metaspace       used 2648K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

Full GC (Ergonomics)：Ergonomics是一种优化垃圾回收的技术，它可以通过调整JVM的参数来控制垃圾回收的行为，以提高应用程序的性能和响应速度，比如JVM内存分配担保机制可能会触发这个gc场景。

PSYoungGen是“Parallel Scavenge Generation”的简写，用来表示收集器时Parallel Scavenge GC的年轻代。

PSOldGen是“Parallel Scavenge Old Generation”的简写，表示老年代是Serial Old GC收集器。

4.2.6-XX:+UseParallelGC

年轻代使用Parallel Scavenge收集器，老年代默认使用Parallel Old收集器，Parallel Scavenge GC（年轻代）+Parallel Old（老年代），这也是JDK8默认的收集器。也可以使用这个组合：-XX:+UseParallelGC -XX:+UseParallelOldGC效果是一样的。

java -Xms30m -Xmx30m -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseParallelGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC输出结果：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(3596348k free), swap 33385592k(6595448k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NewRatio=2 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2023-09-03T14:40:50.751+0800: 0.277: [GC (Allocation Failure) [PSYoungGen: 7292K->880K(9216K)] 7292K->7032K(29696K), 0.0219714 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2023-09-03T14:40:50.774+0800: 0.288: [GC (Allocation Failure) [PSYoungGen: 8208K->904K(9216K)] 14360K->14224K(29696K), 0.0013287 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:40:50.775+0800: 0.289: [Full GC (Ergonomics) [PSYoungGen: 904K->0K(9216K)] [ParOldGen: 13320K->13939K(20480K)] 14224K->13939K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0049257 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2023-09-03T14:40:50.781+0800: 0.294: [Full GC (Ergonomics) [PSYoungGen: 7320K->1024K(9216K)] [ParOldGen: 13939K->20083K(20480K)] 21260K->21107K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0040604 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:40:50.785+0800: 0.299: [Full GC (Ergonomics) [PSYoungGen: 7315K->7168K(9216K)] [ParOldGen: 20083K->20083K(20480K)] 27399K->27252K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0023936 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T14:40:50.788+0800: 0.301: [Full GC (Allocation Failure) [PSYoungGen: 7168K->7168K(9216K)] [ParOldGen: 20083K->20071K(20480K)] 27252K->27240K(29696K), [Metaspace: 2618K->2618K(1056768K)], 0.0040338 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 7476K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 91% used [0x00000000ff600000,0x00000000ffd4d1e8,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
  to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
 ParOldGen       total 20480K, used 20071K [0x00000000fe200000, 0x00000000ff600000, 0x00000000ff600000)
  object space 20480K, 98% used [0x00000000fe200000,0x00000000ff599f10,0x00000000ff600000)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

PSYoungGen是“Parallel Scavenge Generation”的简写，用来表示收集器时Parallel Scavenge GC的年轻代。

ParOldGen是“Parallel Old Generation”的简写，表示老年代是Parallel Old GC收集器。

4.2.7-XX:+UseG1GC

整个堆使用G1收集器，JDK9及之后版本垃圾收集器默认使用G1 GC。

java -Xms30m -Xmx30m -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/gc/gcfile/gc-%p-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m  GcTest

GC日志输出结果如下：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for windows-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 10:21:40 by "rejava" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16608376k(3822244k free), swap 33385592k(6419116k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=31457280 -XX:MaxHeapSize=31457280 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation 
2023-09-03T15:22:22.025+0800: 0.170: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0028444 secs]
   [Parallel Time: 1.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 169.7, Avg: 169.8, Max: 169.9, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.4, Sum: 1.9]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.2, Avg: 0.4, Max: 0.5, Diff: 0.2, Sum: 2.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 12]
      [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.5, Avg: 0.6, Max: 0.7, Diff: 0.3, Sum: 5.0]
      [GC Worker End (ms): Min: 170.4, Avg: 170.4, Max: 170.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.5 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(9216.0K)->0.0B(6144.0K) Survivors: 0.0B->1024.0K Heap: 8192.1K(30.0M)->7952.2K(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2023-09-03T15:22:22.030+0800: 0.175: [GC pause (G1 Humongous Allocation) (young)2023-09-03T15:22:22.127+0800: 0.272: [GC concurrent-root-region-scan-start]
2023-09-03T15:22:22.190+0800: 0.335: [GC concurrent-root-region-scan-end, 0.0631544 secs]
2023-09-03T15:22:22.190+0800: 0.335: [GC concurrent-mark-start]
 (to-space exhausted), 0.1656097 secs]
   [Root Region Scan Waiting: 160.1 ms]
   [Parallel Time: 3.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 335.0, Avg: 335.1, Max: 335.3, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 2.9, Diff: 2.9, Sum: 3.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.8, Diff: 0.8, Sum: 0.8]
      [Object Copy (ms): Min: 0.0, Avg: 0.9, Max: 2.0, Diff: 2.0, Sum: 7.4]
      [Termination (ms): Min: 0.0, Avg: 1.3, Max: 2.7, Diff: 2.7, Sum: 10.6]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 2.6, Avg: 2.8, Max: 2.9, Diff: 0.3, Sum: 22.1]
      [GC Worker End (ms): Min: 337.9, Avg: 337.9, Max: 337.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.9 ms]
      [Evacuation Failure: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(6144.0K)->0.0B(1024.0K) Survivors: 1024.0K->0.0B Heap: 14.9M(30.0M)->14.9M(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.17 secs] 
2023-09-03T15:22:22.196+0800: 0.341: [Full GC (Allocation Failure)  14M->14M(30M), 0.0171827 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 14.9M(30.0M)->14.6M(30.0M)], [Metaspace: 2619K->2619K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.02 secs] 
2023-09-03T15:22:22.213+0800: 0.358: [Full GC (Allocation Failure)  14M->14M(30M), 0.0019567 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 14.6M(30.0M)->14.6M(30.0M)], [Metaspace: 2619K->2619K(1056768K)]
 [Times: user=0.02 sys=0.00, real=0.00 secs] 
2023-09-03T15:22:22.215+0800: 0.360: [GC concurrent-mark-abort]
Heap
 garbage-first heap   total 30720K, used 14952K [0x00000000fe200000, 0x00000000fe3000f0, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

第四行：

2023-09-03T15:22:22.025+0800: 0.170: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0028444 secs]

表示在年轻代（young）进行初始标记（initial-mark）时，发生了一次暂停（pause），持续时间为0.0028444秒。这可能意味着应用程序正在进行大量的内存分配操作，导致垃圾回收器需要花费更多的时间来处理这些操作。

第五行：

[Parallel Time: 1.0 ms, GC Workers: 8]

表示有8个垃圾收集线程在工作，并行处理时间耗时1ms。

G1收集器工作时内存是按region区域划分的，总共有Eden,survivor,old,humongous（大对象存储）这几个区域，垃圾收集就是在这些区域进行标记、筛选回收的。

最后打印的堆信息跟之前的垃圾收集器有明显的区别。

Heap
 garbage-first heap   total 30720K, used 14952K [0x00000000fe200000, 0x00000000fe3000f0, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 2651K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

解释如下：

  • • garbage-first heap：表示使用的是G1垃圾收集器，整个堆空间不再按年代划分。total 30720K, used 14952K：表示整个堆内存大小为30720KB，已经使用了14952KB。[0x00000000fe200000, 0x00000000fe3000f0, 0x0000000100000000)：表示堆内存的起始地址和结束地址范围。

  • • region size 1024K, 1 young (1024K), 0 survivors (0K)：表示当前Region的大小为1024KB，其中有一个Young区（1024KB），没有Survivor区。

  • • Metaspace：表示元数据区的使用情况，包括已使用空间、容量、已提交空间和预留空间。used 2651K, capacity 4486K, committed 4864K, reserved 1056768K：表示元数据区已使用2651KB，总容量为4486KB，已提交空间为4864KB，预留空间为1056768KB。

  • • class space：表示类空间的使用情况，包括已使用空间、容量、已提交空间和预留空间。used 283K, capacity 386K, committed 512K, reserved 1048576K：表示类空间已使用283KB，总容量为386KB，已提交空间为512KB，预留空间为1048576KB。

    4.3相关工具

  • • jvisualvm：JDK自带的JVM分析工具

  • • gceasy：线上GC日志分析

地址：https://gceasy.io/,上传GC日志即可进行分析，各个维度的度量和数据及图表一应俱全，很方便。

新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

  • • Eclipse memory Analyzer(MAT)

下载地址：https://eclipse.dev/mat/。这是一个内存泄漏分析工具，发生OOM时可配置导出堆内存数据文件，然后导入到该工具进行分析定位。有两种方法导出堆内存数据。

  • • 可使用jmap命令（只要JVM运行着都可以使用），用法：jmap -dump:live,format=b,file=path pid，例如：jmap -dump:live,format=b,file=dump.hprof 14716

  • • 使用JVM参数（内存溢出时自动dump堆内存数据）：-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=path，比如：-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:/gc/dump.hprof。

    4.4GC 日志的优化和调优技巧

  • • 分析 GC 日志的时间戳，可以了解垃圾回收事件的发生频率和间隔。

  • • 查看不同内存区域的容量变化，可以判断应用程序的内存使用情况和垃圾回收的效果。

  • • 关注垃圾回收的耗时，如果耗时过长，可能会导致应用程序的停顿或性能下降。

  • • 比较不同垃圾回收器的性能指标，选择适合应用程序需求的垃圾回收器。

  • • 注意内存分配速率，如果过高可能会导致频繁的垃圾回收和内存压力。

    4.5总结

    GC日志分析是优化Java应用程序性能和稳定性的重要手段。通过分析GC日志，我们可以了解垃圾回收器的行为、内存使用情况和相关的性能指标，从而进行优化和调优等，提高应用程序的性能和稳定性。同时，合理使用工具和技巧，如gceasy、MAT等工具可以更高效地进行GC日志分析工作。因此，深入理解JVM GC日志分析对于Java开发人员来说是非常重要的。

内容相关推荐阅读：

欢迎关注公众号，欢迎分享、点赞、在看


原文始发于微信公众号（小新成长之路）：新来的技术总监：谁再不会分析JVM GC日志，直接给我滚蛋

版权声明：本文内容由互联网用户自发贡献，该文观点仅代表作者本人。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如发现本站有涉嫌侵权/违法违规的内容， 请发送邮件至 举报，一经查实，本站将立刻删除。

文章由极客之音整理，本文链接：https://www.bmabk.com/index.php/post/238346.html

赞 (0)
小半的头像小半
0 0

相关推荐

发表回复

登录后才能评论
极客之音——专业性很强的中文编程技术网站，欢迎收藏到浏览器，订阅我们！