JVM调优的GC日志观察解读

如果各项参数设置合理，系统没有超时日志出现，GC 频率不高，GC 耗时不高，那么没有必要进行 GC 优化
如果 GC 时间超过 1-3 秒，或者频繁 GC，则必须优化。

一、参数解读

1. Jvm 调优典型参数设置;
   -Xms: 堆内存的最小值 ：默认情况下，当堆中可用内存小于 40%时，堆内存会开始增加，一直增加到-Xmx 的大小。
   -Xmx :堆内存的最大值：默认值是总内存/64（且小于 1G）,默认情况下，当堆中可用内存大于 70%时，堆内存会开始减少，一直减小到-Xms的大小；
   -Xmn: 新生代内存的最大值：包括 Eden 区和两个 Survivor 区的总和，配置写法如：-Xmn1024k，-Xmn1024m，-Xmn1g
   -Xss: 每个线程的栈内存：默认 1M，一般来说是不需要改。线程栈越小意味着可以创建的线程数越多

整个堆的大小 = 年轻代大小 + 年老代大小，堆的大小不包含元空间大小，如果增大了年轻代，年老代相应就会减小，官方默认的配置为年老代大小/年轻代大小=2/1 左右；
建议在开发测试环境可以用 Xms 和 Xmx 分别设置最小值最大值，但是在线上生产环境，Xms 和 Xmx 设置的值必须一样，防止抖动；

2. GC 日志
   -XX:+PrintGCDetails 开启 GC 日志创建更详细的 GC 日志 ，默认情况下，GC 日志是关闭的
   -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps ：开启 GC 时间提示
   开启时间便于我们更精确地判断几次 GC 操作之间的时两个参数的区别
   时间戳是相对于 0 （依据 JVM 启动的时间）的值，而日期戳（date stamp）是实际的日期字符串
   由于日期戳需要进行格式化，所以它的效率可能会受轻微的影响，不过这种操作并不频繁，它造成的影响也很难被我们感知。
   -XX:+PrintHeapAtGC 打印堆的 GC 日志
   -Xloggc:./logs/gc.log 指定 GC 日志路径

3. jdk11的gc日志打印
   -Xlog:gc*:file=gc.log:time,uptime,pid,tid,tags:filecount=5,filesize=10M

gc.log是日志打印位置

二、打印日志出来

package com.zhk.study.log;

import java.util.ArrayList;
import java.util.List;

//测试代码
public class TestHeap {

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

class Heap {
  String HeapName = "Java Heap 测试";
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

1.jdk8

配置jvm参数

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-Xloggc:E:/gc-default.log
1
2
3
4
5

1. 日志解读

2022-08-05T13:45:23.336+0800: 4.866: [GC (Metadata GC Threshold) [PSYoungGen: 136353K->20975K(405504K)] 160049K->48437K(720384K), 0.0092260 secs] [Times: user=0.00 sys=0.02, real=0.02 secs]
1

2022-08-05T13:45:23.336+0800: 本次GC发生时间
4.866: 举例启动应用的时间
[GC【表示GC的类型，youngGC】 (Metadata GC Threshold) 元空间超阈值
[PSYoungGen: 136353K->20975K(405504K年轻代总空间)] 160049K->48437K(720384K)整堆), 0.0092260 secs本次垃圾回收耗时]
[Times: user=0.00本次GC消耗CPU的时间 sys=0.02系统暂停时间, real=0.02 secs实际应用暂停时间]
1
2
3
4
5

2. FullGC 日志含义

2022-08-05T20:24:47.815+0800: 6.955: [Full GC (Metadata GC Threshold) [PSYoungGen: 701K->0K(72704K)] [ParOldGen: 38678K->35960K(175104K)] 39380K->35960K(247808K), [Metaspace: 56706K->56706K(1099776K)], 0.1921975 secs] [Times: user=1.03 sys=0.00, real=0.19 secs]
1

2022-08-05T20:24:47.815+0800:
6.955: 刚启动服务就Full GC【整堆回收！！】

[Full GC (Metadata GC Threshold) Metaspace空间超限！
[PSYoungGen: 701K->0K(72704K)] 年轻代没有回收空间
[ParOldGen: 38678K->35960K(175104K)] 39380K->35960K(247808K), 老年代也没有到阈值，整堆更没有到阈值
[Metaspace: 56706K->56706K(1099776K)], 0.1921975 secs]
[Times: user=1.03本次GC消耗CPU的时间 sys=0.00系统暂停时间, real=0.19 secs实际应用暂停时间]
1
2
3
4
5
6
7
8

2、jdk11默认G1回收

启动参数修改为

-Xlog:gc*:file=gc.log:time,uptime,pid,tid,tags:filecount=5,filesize=10M
1

1. 日志解读

[2023-09-14T11:38:32.994+0800][0.017s][12940][11992][gc,heap] Heap region size: 1M
[2023-09-14T11:38:33.001+0800][0.024s][12940][11992][gc     ] Using G1
[2023-09-14T11:38:33.001+0800][0.024s][12940][11992][gc,heap,coops] Heap address: 0x0000000701c00000, size: 4068 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[2023-09-14T11:38:33.201+0800][0.225s][12940][8148 ][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2023-09-14T11:38:33.202+0800][0.225s][12940][8148 ][gc,task      ] GC(0) Using 3 workers of 3 for evacuation
[2023-09-14T11:38:33.215+0800][0.238s][12940][8148 ][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.0ms
[2023-09-14T11:38:33.215+0800][0.238s][12940][8148 ][gc,phases    ] GC(0)   Evacuate Collection Set: 12.7ms
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,phases    ] GC(0)   Post Evacuate Collection Set: 0.2ms
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,phases    ] GC(0)   Other: 0.3ms
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,heap      ] GC(0) Eden regions: 12->0(10)
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,heap      ] GC(0) Survivor regions: 0->2(2)
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,heap      ] GC(0) Old regions: 0->7
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,heap      ] GC(0) Humongous regions: 4->4
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,metaspace ] GC(0) Metaspace: 6551K->6551K(1056768K)
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 16M->12M(256M) 14.012ms
[2023-09-14T11:38:33.215+0800][0.239s][12940][8148 ][gc,cpu       ] GC(0) User=0.03s Sys=0.02s Real=0.01s
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

这段日志描述了Java应用程序的垃圾收集事件的详细信息。让我解释一下每个部分的含义：
[2023-09-14T11:38:32.994+0800] - 这是时间戳，表示日志记录的时间。

[0.017s] - 这是相对于日志记录的时间的时间戳，表示日志记录发生的相对时间。

[12940][11992] - 这两个数字可能是线程的标识符，用于标识执行垃圾收集的线程。

[gc,heap] Heap region size: 1M - 这表示Java堆的分区大小为1MB。

[gc] Using G1 - 这表示Java使用了G1垃圾收集器。

[gc,heap,coops] Heap address: 0x0000000701c00000, size: 4068 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 - 这描述了Java堆的地址、大小以及压缩指针（Compressed Oops）的信息。

[gc,start] GC(0) Pause Young (Normal) (G1 Evacuation Pause) - 这是垃圾收集事件的开始，GC(0) 表示第0次垃圾收集，Pause Young (Normal) (G1 Evacuation Pause) 表示这是一次Young代正常的G1垃圾收集事件。

[gc,task] GC(0) Using 3 workers of 3 for evacuation - 这表示在这次垃圾收集事件中，有3个工作线程用于执行对象的迁移。

[gc,phases] - 这一系列的行描述了垃圾收集的不同阶段，包括 Pre Evacuate Collection Set、Evacuate Collection Set、Post Evacuate Collection Set 等。

[gc,heap] - 这行提供了有关堆内存的信息，包括Eden、Survivor、Old、Humongous等区域的变化。

[gc,metaspace] - 这行提供了有关元数据空间（Metaspace）的信息，包括它的大小变化。

[gc] Pause Young (Normal) (G1 Evacuation Pause) 16M->12M(256M) 14.012ms - 这行提供了垃圾收集事件的摘要信息，包括收集前后的堆内存使用量变化，以及事件的持续时间。

[gc,cpu] - 这行提供了垃圾收集事件的CPU占用情况。

总的来说，这些日志记录提供了关于Java应用程序中垃圾收集事件的详细信息，包括时间戳、线程标识、垃圾收集器类型、堆内存情况以及事件持续时间等。这些信息对于分析和调整Java应用程序的性能非常有用。

三、优化

优化垃圾回收性能通常需要仔细分析应用程序的行为和垃圾回收日志，然后根据分析的结果采取相应的措施。以下是一些可能的优化建议，但请注意，具体的优化策略会根据应用程序的需求和行为而变化：

• 分析垃圾回收模式：首先要了解应用程序的垃圾回收模式。从日志中可以看出，这里使用的是G1（Garbage-First）垃圾回收器。不同的垃圾回收器适用于不同的应用程序，因此确保选择了最适合应用程序需求的回收器是很重要的。

• 调整堆大小：根据应用程序的需求，可能需要调整堆大小（-Xms 和 -Xmx 参数）。如果应用程序频繁触发垃圾回收，可能需要增加堆大小以减少回收的频率。但要注意，堆大小的过分增加也可能导致长时间的垃圾回收停顿，因此需要谨慎调整。

• 分析垃圾回收暂停时间：从日志中可以看到每次Young区和Mixed区垃圾回收的停顿时间。优化的目标是减少这些停顿时间，以提高应用程序的响应性。可以使用参数来控制垃圾回收暂停时间，例如使用 -XX:MaxGCPauseMillis 参数。

• 分析内存分配模式：查看日志中的Eden、Survivor和Old区的分配情况。如果发现频繁的对象进入Old区，可能需要调整各个区域的大小或者调整年轻代的比例，以减少对象在Old区的存活时间。

• 检查Metaspace使用：从日志中可以看到Metaspace的使用情况。如果Metaspace的使用不断增长，可能需要增加Metaspace的大小或者检查是否有类加载器泄漏。

• 分析对象生命周期：了解应用程序中对象的生命周期模式，可以帮助确定何时进行垃圾回收。如果对象的生命周期很短，可以采用更侧重于Young区的策略。如果对象生命周期很长，需要确保Old区的管理足够高效。

• 监控和调整：使用性能监控工具和垃圾回收日志持续监控应用程序的性能。如果发现性能问题，可以根据实时数据来调整垃圾回收参数。

• 并行和并发：根据应用程序的特性，可以选择并行垃圾回收或并发垃圾回收。并行回收器适用于多核系统，而并发回收器适用于需要最小停顿时间的应用程序。

• 分析吞吐量：了解应用程序的吞吐量需求，可以选择适当的垃圾回收策略。某些垃圾回收器更适合高吞吐量，而某些回收器更适合低停顿时间。

• 版本升级：考虑将JVM版本升级到最新的稳定版本，因为新版本通常会带来性能和垃圾回收方面的改进。

综上所述，优化垃圾回收性能是一个复杂的过程，需要深入了解应用程序的行为和需求。建议在开发和测试环境中进行多次测试和调整，以找到最佳的垃圾回收配置。同时，密切关注生产环境中的性能指标，以及随着应用程序负载变化而进行必要的调整。

四、gc次数判断

gc次数