贫瘠之地

华北无浪漫，死海扬起帆
多少个夜晚，独自望着天

0%

读懂 GC 日志

发表于 分类于 >

当使用 Java 或任何其他基于 JVM 的编程语言时，其中一个核心功能是内存清理（垃圾回收）

和 C 和 C++ 等语言不同，使用者不需要关注内存相关的操作，例如 malloc、calloc、realloc、free 等函数

释放内存的操作就是由 JVM 中名为 Garbage Collector 的角色完成的

垃圾回收器是如何工作的

JVM 在后台运行垃圾回收器来查找未使用的引用，这些引用占用的内存可以被释放并重新使用

堆内存被划分为不同的区域，每个区域都有自己的垃圾收集器类型

垃圾回收器有很多种实现，同时 JVM 在符合规范的情况下也会有不同的实现，在理论和实践中每个 JVM 实现都可以提供自己的垃圾收集器实现，从而提供不同的性能

JVM 堆的三个主要区域的简化视图可以可视化如下：

拥有一个健康的垃圾收集过程是实现基于 JVM 的应用程序的最佳性能的关键，因此我们需要确保监控 Java 虚拟机及其垃圾回收器，通过 GC logs，我们可以了解 JVM 的垃圾收集器的工作

什么是 GC 日志

垃圾收集器日志是 Java 虚拟机生成的文本文件，用于描述垃圾收集器的工作

包含查看内存清理过程如何工作所需的所有信息，提供了垃圾收集器的行为以及它使用了多少资源；尽管我们可以使用 APM 提供程序或内部构建的监控工具来监控我们的应用程序，但垃圾收集器日志对于快速识别堆内存利用率方面的任何潜在问题和瓶颈将是非常宝贵的

下面是一个 GC 日志的示例

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=52428800 -XX:+ManagementServer -XX:MaxGCPauseMillis=200 -XX:MaxHeapSize=52428800 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:-PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:-UseAdaptiveSizePolicy -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2024-05-11T15:55:49.541-0800: 0.517: [GC (Allocation Failure)  12800K->2492K(49152K), 0.0021661 secs]
2024-05-11T15:55:49.710-0800: 0.687: [GC (Allocation Failure)  15292K->3412K(49152K), 0.0025412 secs]
2024-05-11T15:55:49.810-0800: 0.787: [GC (Allocation Failure)  16212K->4807K(49152K), 0.0024151 secs]
2024-05-11T15:55:49.899-0800: 0.876: [GC (Allocation Failure)  17607K->6061K(49152K), 0.0021924 secs]
2024-05-11T15:55:49.997-0800: 0.973: [GC (Allocation Failure)  18861K->7424K(49152K), 0.0029084 secs]
2024-05-11T15:55:50.076-0800: 1.053: [GC (Allocation Failure)  20224K->8503K(49152K), 0.0023001 secs]
2024-05-11T15:55:50.112-0800: 1.089: [GC (Allocation Failure)  21303K->9742K(49152K), 0.0025567 secs]
2024-05-11T15:55:50.153-0800: 1.129: [GC (Allocation Failure)  22542K->10927K(49152K), 0.0025338 secs]
2024-05-11T15:55:50.192-0800: 1.168: [GC (Allocation Failure)  23727K->12205K(49152K), 0.0027763 secs]
2024-05-11T15:55:50.298-0800: 1.275: [GC (Allocation Failure)  25005K->13338K(49152K), 0.0041218 secs]
2024-05-11T15:55:50.394-0800: 1.371: [GC (Metadata GC Threshold)  24027K->14554K(49152K), 0.0026052 secs]
2024-05-11T15:55:50.397-0800: 1.373: [Full GC (Metadata GC Threshold)  14554K->8390K(49152K), 0.0282067 secs]
2024-05-11T15:55:50.472-0800: 1.448: [GC (Allocation Failure)  21190K->9606K(49152K), 0.0011170 secs]
2024-05-11T15:55:50.553-0800: 1.530: [GC (Allocation Failure)  22406K->10211K(49152K), 0.0021453 secs]
2024-05-11T15:55:50.625-0800: 1.602: [GC (Allocation Failure)  23011K->10545K(49152K), 0.0015239 secs]
2024-05-11T15:55:50.722-0800: 1.698: [GC (Allocation Failure)  23345K->11492K(49152K), 0.0021307 secs]
2024-05-11T15:55:50.810-0800: 1.786: [GC (Allocation Failure)  24292K->12785K(49152K), 0.0017124 secs]

启动 GC 日志

在现代设备上，启用垃圾收集器日志时不必担心性能问题，理论上应该始终打开 Java 垃圾收集日志

对于 Java 8 及更早版本，通过如下参数启动

1
-XX:+PrintGCDetails -Xloggc:<PATH_TO_GC_LOG_FILE>

其中 PATH_TO_GC_LOG_FILE 是日志文件存放的位置

1
java -XX:+PrintGCDetails -Xloggc:/home/shared/log/gc.log -jar my_app.jar


对于 Java 9 及更新版本，可以简化上面的命令

1
-Xlog:gc*:file=<PATH_TO_GC_LOG_FILE>
1
java -Xlog:gc*:file=/home/shared/gc.log -jar my_app.jar

Java 9 及更新的版本还支持 GC 调试日志，会输入更详细的日志内容，通过如下配置设置

1
-Xlog:gc*,gc+phases=debug

一旦启用了 GC 日志，那么需要注意轮换（rotation）的重要配置，当使用较旧的 JVM 版本（如 JDK 8）时，可能需要轮换 GC 日志

有以下参数进行控制：

  • -XX:+UseGCLogFileRotation 启用日志轮换
  • -XX:NumberOfGCLogFiles 设置保留多少 GC 日志文件，例如 -XX:NumberOfGCLogFiles=10 将保留最多 10 个 GC 日志文件
  • -XX:GCLogFileSize 单个 GC 日志文件可以有多大，例如 -XX/GCLogFileSize=10m 将在日志文件达到 10 MB 时覆盖 GC 日志文件

开启 GC 日志后，就可以根据日志进行分析了

如何分析

垃圾收集日志将能够回答以下问题：

  • Young 区什么时候进行的 GC
  • Old 区什么时候进行的 GC
  • 运行了多少次 GC
  • GC 一共进行了多长时间
  • GC 前后的内存利用率是多少

下面来看一个 JVM 垃圾收集器日志中的示例，并分析每个片段，突出显示其背后的关键部分

PS + CMS

一行日志如下

1
2019-10-30T11:13:00.920-0100: 6.399: [Full GC (Allocation Failure) 2019-10-30T11:13:00.920-0100: 6.399: [CMS: 43711K->43711K(43712K), 0.1417937 secs] 63359K->48737K(63360K), [Metaspace: 47130K->47130K(1093632K)], 0.1418689 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]

第一部分是时间，可以看到这条日志是在 2019-10-30T11:13:00.920-0100 产生的

第二部分是 GC 的类型，可以看到日志的类型是 Full GC

对于 GC 的类型有如下三种

  • Minor GC：当 Eden 区已满或即将满时触发，如果应用会频繁创建新对象，那么这个 GC 会经常进行；Eden 区和 Survivor 不会产生碎片
  • Major GC：Major GC 意味着产生了老年代的 GC，根据不同垃圾收集器的设置，该操作可能发生的更少或者更频繁
  • Full GC：完全收集，表示年轻代和老年代都会进行收集；通过标记、扫描、压缩的步骤避免内存碎片

Major 和 Full GC 没有严格区分，不要特别在意，见 https://stackoverflow.com/questions/50081873/full-garbage-collection-vs-major-garbage-collection

第三部分是进行 GC 的原因，可以看到该日志的原因是 Allocation Failure，通常意味着堆内存的 Eden 区中没有空间用于新对象分配，垃圾收集器试图为新对象释放一些内存

再次更详细地了解这行日志：

JVM 垃圾收集器给我们的一条非常重要的信息是应用程序线程停止的总时间，应该预期线程会经常停止，但时间很短

1
2019-10-29T10:00:28.879-0100: 0.488: Total time for which application threads were stopped: 0.0001006 seconds, Stopping threads took: 0.0000065 seconds

可以看到线程停止了 0.0001006 秒，线程的停止花费了 0.0000065 秒，我们将在 GC logs 中一次又一次地看到这样的信息

应该引起一个危险信号的是长线程停止时间——也称为 stop the world，它的发生将基本停止整个应用，例如

1
2019-11-02T17:11:54.259-0100: 7.438: Total time for which application threads were stopped: 11.2305001 seconds, Stopping threads took: 0.5230011 seconds

在上面的日志行中，我们可以看到应用程序线程停止的时间超过了 11 秒，意味着应用程序没有响应的时间超过了 11 秒，应该不惜一切代价避免出现这种情况

G1

使用如下配置来设置使用 G1 垃圾回收器

1
2
3
-XX:+UseG1GC
-XX:-UseConcMarkSweepGC
-XX:-UseCMSInitiatingOccupancyOnly

G1 的日志如下所示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
2019-11-03T21:26:21.827-0100: 2.069: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2097152 bytes, new threshold 15 (max 15)
- age   1:     341608 bytes,     341608 total
, 0.0021740 secs]
   [Parallel Time: 0.9 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 2069.4, Avg: 2069.5, Max: 2069.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5]
      [Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 2.3]
         [Processed Buffers: Min: 1, Avg: 1.4, Max: 4, Diff: 3, Sum: 14]
      [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.3, Max: 0.3, Diff: 0.1, Sum: 3.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 10]
      [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.6, Avg: 0.7, Max: 0.8, Diff: 0.1, Sum: 7.0]
      [GC Worker End (ms): Min: 2070.2, Avg: 2070.2, Max: 2070.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 26.0M(26.0M)->0.0B(30.0M) Survivors: 5120.0K->3072.0K Heap: 51.4M(64.0M)->22.6M(64.0M)]
 [Times: user=0.01 sys=0.00, real=0.01 secs]

上面的日志展示了一次年轻代的 GC 事件 [GC pause (G1 Evacuation Pause) (young)

导致一些内存区域被清理 [Eden: 26.0M(26.0M)->0.0B(30.0M) Survivors: 5120.0K->3072.0K Heap: 51.4M(64.0M)->22.6M(64.0M)]

还可以看到时间和 CPU 的相关信息 [Times: user=0.01 sys=0.00, real=0.01 secs]

下面是更详细的内存信息摘要

  • Eden 区被完全清空了
  • Survivors 的空间由 5120K 降为 3072K
  • 整个堆的空间从 64 MB 的总大小中的 51.4 MB 开始，到 22.6 MB 结束

除此之外，还可以看到有关并行垃圾收集器工作程序内部及其工作阶段（如启动、扫描和工作）的更详细信息

还可以看到与 G1 垃圾收集器相关的其他日志条目

1
2
3
4
5
6
7
8
9
10
2019-11-03T21:26:23.704-0100: 2019-11-03T21:26:23.704-0100: 3.946: 3.946: [GC concurrent-root-region-scan-start]
Total time for which application threads were stopped: 0.0035771 seconds, Stopping threads took: 0.0000111 seconds
2019-11-03T21:26:23.706-0100: 3.948: [GC concurrent-root-region-scan-end, 0.0017994 secs]
2019-11-03T21:26:23.706-0100: 3.948: [GC concurrent-mark-start]
2019-11-03T21:26:23.737-0100: 3.979: [GC concurrent-mark-end, 0.0315921 secs]
2019-11-03T21:26:23.737-0100: 3.979: [GC remark 2019-11-03T21:26:23.737-0100: 3.979: [Finalize Marking, 0.0002017 secs] 2019-11-03T21:26:23.738-0100: 3.980: [GC ref-proc, 0.0004151 secs] 2019-11-03T21:26:23.738-0100: 3.980: [Unloading, 0.0025065 secs], 0.0033738 secs]
 [Times: user=0.04 sys=0.01, real=0.01 secs]
2019-11-03T21:26:23.741-0100: 3.983: Total time for which application threads were stopped: 0.0034705 seconds, Stopping threads took: 0.0000308 seconds
2019-11-03T21:26:23.741-0100: 3.983: [GC cleanup 54M->54M(64M), 0.0004419 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

日志为我们提供了有关应用程序线程停止的总时间、垃圾收集器所做清理的结果以及所使用的资源的信息

补充

OutOfMemory 错误

Java heap space

  • 对象不能被分配进堆内存
  • 过大的流量
  • 应用中引用持有过多，导致无法回收足够的空间（泄漏）
  • 应用中使用了过多的 Finalizers，Finalizers 的对象不会立即进行 GC，会通过相关的守护线程在队列中执行，有时线程会跟不上队列（生产大于消费）

处理

  • 增加堆内存大小 -Xmx（GB -> G or g | MB -> M or m | KB -> K or k）
  • 修复应用中的内存泄漏

GC overhead limit exceeded

  • Java 进程花费了 98% 以上的时间进行垃圾收集，回收的内存不到 2%，而且到目前为止已经连续进行了 5 次垃圾收集（编译时常量）

处理

  • 增加堆内存大小 -Xmx
  • GC 开销限制可以调整 -XX:- UseGCOverheadLimit
  • 修复应用中的内存泄漏

Unable to create new native thread

  • 没有足够的空间创建新的线程

处理

  • 为服务器分配更多内存
  • 增加堆内存大小
  • 修复应用中的线程泄漏
  • 增加 OS 的限制 ulimit -a max user processes (-u) 1800
  • 通过 -Xss 参数减少线程栈的大小

Permgen space

  • 永久代的内容包括
    • Class 对象的名字、变量、方法
    • 与类关联的对象数组和类型数组
    • JIT 优化（Just In Time）

处理

  • 增加永久代的大小 -XX:MaxPermSize
  • 重新启动 JVM

Metaspace

  • Java 8 之后永久代被元空间取代，Class 相关的元数据被分配在 native memory 中（称为元空间），如果元空间耗尽，则会抛出该错误

处理

  • 如果设置了 -XX:MaxMetaSpaceSize ，则增加其值
  • 移除 -XX:MaxMetaSpaceSize
  • 减少 Java 堆内存大小，分配更多的内存给元空间
  • 为服务器分配更多内存
  • 应用中可能存在 bug

Requested array size exceeds VM limit

  • 应用尝试分配一个大于堆内存的数组

处理

  • 增加堆内存大小 -Xmx
  • 修复 bug，大概率不需要一个巨大的数组

Kill process or sacrifice child

  • Kernel Job – Out of Memory Killer 进程将会在内存不足情况下被终止

和其他 OOM 不同，这个OOM 是由操作系统触发

处理

  • 将进程迁移到其他计算机
  • 给机器增加内存

reason stack_trace_with_native_ method

  • native 方法遇到分配失败
  • 打印堆栈跟踪，其中底层是 native 方法

处理

  • 结合 OS 进行分析

JVM 运维工具

jps

jps - Lists the instrumented Java Virtual Machines (JVMs) on the target system. This command is experimental and unsupported.

列出目标系统上的可观测的 Java 虚拟机（JVM）

1
jps [ options ] [ hostid ]
1
2
3
4
5
6
jps -l

24947 org.jetbrains.jps.cmdline.Launcher
29863 sun.tools.jps.Jps
43962 org.jetbrains.jps.cmdline.Launcher
34074 com.intellij.idea.Main

jstat

jstat - Monitors Java Virtual Machine (JVM) statistics. This command is experimental and unsupported.

用于监控 Java 虚拟机（JVM）统计信息的命令

使用 jstat 命令，可以获取有关堆内存、垃圾回收、类加载、线程和编译等方面的数据

1
jstat [ generalOption | outputOptions vmid [ interval[s|ms] [ count ] ]
1
2
3
4
5
6
7
8
jstat -gccause 34074 1000 5

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
  0.00  94.67  93.44  33.98  99.05  96.95   2101  503.477     9   65.924  569.401 No GC                G1 Evacuation Pause
  0.00  91.63  45.07  33.34  99.05  96.95   2101  504.128     9   65.924  570.052 G1 Evacuation Pause  No GC
  0.00  91.63  59.15  33.34  99.05  96.95   2101  504.128     9   65.924  570.052 G1 Evacuation Pause  No GC
  0.00  91.63  60.56  33.34  99.05  96.95   2101  504.128     9   65.924  570.052 G1 Evacuation Pause  No GC
  0.00  91.63  61.97  33.34  99.05  96.95   2101  504.128     9   65.924  570.052 G1 Evacuation Pause  No GC

以 gccause 查看堆内存为例，这里表格标头分别代表

name meaning
S0 Survivor 0 区占用百分比
S1 Survivor 1 区占用百分比
E Eden 区占用百分比
O 老年代占用百分比
M 元空间占用百分比
CCS 压缩类空间占用百分比
YGC young GC 发生次数
YGCT yong GC 垃圾回收时间
FGC full GC 发生次数
FGCT full GC 垃圾回收时间
GCT 总共的垃圾回收时间
LGCC 最后一次 GC 的原因
GCC 当前 GC 的原因

jstack

jstack - Prints Java thread stack traces for a Java process, core file, or remote debug server. This command is experimental and unsupported.

输出 Java 进程、核心文件或远程调试服务器的 Java 线程堆栈跟踪

1
2
3
jstack [ options ] pid
jstack [ options ] executable core
jstack [ options ] [ server-id@ ] remote-hostname-or-IP

jmap

jmap - Prints shared object memory maps or heap memory details for a process, core file, or remote debug server.

打印进程、核心文件或远程调试服务器的共享对象内存映射或堆内存详细信息

1
2
3
jmap [ options ] pid
jmap [ options ] executable core
jmap [ options ] [ pid ] server-id@ ] remote-hostname-or-IP

这里直接使用会报错（MacOS）

1
2
3
4
5
Attaching to process ID 34074, please wait...
ERROR: attach: task_for_pid(34074) failed: '(os/kern) failure' (5)
Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process. Could be caused by an incorrect pid or lack of privileges.
sun.jvm.hotspot.debugger.DebuggerException: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process. Could be caused by an incorrect pid or lack of privileges.
...

因为新版的 Linux 系统加入了 ptrace-scope 机制，该机制的目的是防止用户访问正在执行的进程的内存，但是如 jinfo、jmap 这些调试类工具本身就是利用 ptrace 来获取执行进程的内存等信息

一些文章给出的解决方案需要修改内核参数，可以参考

Error attaching to process sun.jvm.hotspot.debugger.DebuggerException cannot open binary file_sun.jvm.hotspot.debugger.debuggerexception: cannot-CSDN博客

担保机制与 Ergonomics

在 PS + PO 日志中可以看到

1
2024-05-11T15:56:45.857-0800: 56.923: [Full GC (Ergonomics)  46904K->46903K(49152K), 0.1493527 secs]

日志中 GC 的原因是 Ergonomics，在一些文章中把原因称为因为担保导致的 GC，实际上是不准确的

担保机制

担保机制的官方术语称为 Guarantee

-XX:+HandlePromotionFailure

The youngest generation collection does not require a guarantee of full promotion of all live objects. (Introduced in 1.4.2 update 11) [5.0 and earlier: false.]

发生 GC 时，当老年代剩余空间小于平均年轻代向老年代晋升的空间大小，就会进行一次 Full GC

Ergonomics

Ergonomics 是一种 JVM 自动优化手段

https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/ergonomics.html#ergonomics

JVM 会根据一些配置自动调整堆内存的大小：

  • Maximum Pause Time Goal：期望最大暂停时间
  • Throughput Goal：吞吐量目标，例如 -XX:GCTimeRatio=19 是将垃圾收集的目标设置为总时间的 5%
  • Footprint Goal：如果已经达到吞吐量和最大暂停时间目标，那么垃圾收集器会减小堆的大小，直到其中一个目标（总是吞吐量目标）无法达到为止

调优的策略

  • 除非您知道需要一个大于默认最大堆大小的堆，否则不要为堆选择最大值，应该选择一个足以满足应用程序的吞吐量目标
  • 堆将增长或收缩到支持所选吞吐量目标的大小。应用程序行为的更改可能会导致堆增长或收缩。例如如果应用程序开始以更高的速率进行分配，则堆将增长以保持相同的吞吐量。
  • 如果堆增长到其最大大小，并且没有达到吞吐量目标，则最大堆大小对于吞吐量目标来说太小，应该将最大堆大小设置为一个值，该值接近平台上的总物理内存，但不会导致应用程序的交换（swapping），再次执行应用程序，如果仍未达到吞吐量目标那么说明应用程序时间的目标对于平台上的可用内存来说太高了（机器内存不足）
  • 如果可以达到吞吐量目标，但暂停时间过长，则选择最大暂停时间目标，选择最长暂停时间目标可能意味着无法达到吞吐量目标，因此选择对应用程序来说可以接受的折衷值
  • 通常情况下堆的大小会随着垃圾收集器试图满足竞争目标而波动，即使应用程序已达到稳定状态，也是如此实现吞吐量目标（可能需要更大的堆）的压力与最大暂停时间和最小内存占用（两者都可能需要小堆）的目标相竞争

Ergonomics 操作可以通过参数 -XX:-UseAdaptiveSizePolicy 来进行关闭


我这里启动了一个服务，分配了足够小的内存，不断创建对象直到发生 OOM

1
-Xms50m -Xmx50m -Xloggc:/Users/guorunze/temp/log/gc.log -XX:+PrintGCDateStamps -XX:-PrintGCDetails -XX:MaxGCPauseMillis=200

默认开启

1
2
3
4
5
6
7
8
9
10
11
12
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
2048.0 2048.0 1268.1  0.0   12800.0   3632.7   34304.0    14786.9   39600.0 36885.3 5296.0 4742.0     40    0.094   2      0.089    0.183
2048.0 2048.0 1268.1  0.0   12800.0   3632.7   34304.0    14786.9   39600.0 36885.3 5296.0 4742.0     40    0.094   2      0.089    0.183
2048.0 4096.0 2032.9  0.0    8704.0   2406.1   34304.0    19640.4   41008.0 38297.3 5424.0 4929.8     42    0.103   2      0.089    0.192
5632.0 5632.0  0.0   3465.9  5632.0   994.9    34304.0    27764.1   41392.0 38739.4 5552.0 4985.5     45    0.118   2      0.089    0.207
5632.0 5632.0  0.0    0.0    5632.0    0.0     34304.0    31724.0   41392.0 38545.4 5552.0 4952.5     46    0.124   4      0.433    0.556
5632.0 5632.0  0.0    0.0    5632.0   4387.9   34304.0    34278.5   41392.0 38545.5 5552.0 4952.5     46    0.124   8      0.778    0.902
5632.0 5632.0  0.0    0.0    5632.0   5604.6   34304.0    34115.6   41648.0 38718.9 5552.0 4986.1     46    0.124  13      1.648    1.771
5632.0 5632.0  0.0    0.0    5632.0   5581.2   34304.0    34114.0   41904.0 39071.1 5552.0 5027.2     46    0.124  17      2.409    2.532
5632.0 5632.0  0.0    0.0    5632.0   5599.6   34304.0    34114.0   41904.0 39071.1 5552.0 5027.2     46    0.124  17      2.409    2.532
5632.0 5632.0  0.0    0.0    5632.0   4822.1   34304.0    34110.1   41904.0 39111.5 5552.0 5035.1     46    0.124  20      2.833    2.957
5632.0 5632.0  0.0    0.0    5632.0   4836.1   34304.0    34110.1   41904.0 39111.5 5552.0 5035.1     46    0.124  20      2.833    2.957

关闭

1
2
3
4
5
6
7
8
9
10
11
12
13
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
2048.0 2048.0 2043.5  0.0   12800.0   1071.0   34304.0    17905.8   39600.0 37015.0 5296.0 4774.8     32    0.112   2      0.085    0.197
2048.0 2048.0 2043.5  0.0   12800.0   1071.0   34304.0    17905.8   39600.0 37015.0 5296.0 4774.8     32    0.112   2      0.085    0.197
2048.0 2048.0 2043.5  0.0   12800.0   1071.0   34304.0    17905.8   39600.0 37015.0 5296.0 4774.8     32    0.112   2      0.085    0.197
2048.0 2048.0 2043.5  0.0   12800.0   9275.9   34304.0    17905.8   39600.0 37015.0 5296.0 4774.8     32    0.112   2      0.085    0.197
2048.0 2048.0  0.0   2032.0 12800.0    0.0     34304.0    30780.1   41392.0 38723.6 5552.0 4988.0     35    0.147   3      0.085    0.232
2048.0 2048.0 2025.9  0.0   12800.0    0.0     34304.0    29831.1   41392.0 38661.2 5552.0 4974.4     36    0.152   4      0.249    0.401
2048.0 2048.0  0.0    0.0   12800.0   9340.6   34304.0    34087.4   41392.0 38510.8 5552.0 4952.2     36    0.152   6      0.691    0.843
2048.0 2048.0  0.0    0.0   12800.0  12800.0   34304.0    34083.5   41392.0 38510.8 5552.0 4952.2     36    0.152  10      1.101    1.253
2048.0 2048.0  0.0    0.0   12800.0  12800.0   34304.0    33978.9   41392.0 38510.8 5552.0 4952.2     36    0.152  16      2.011    2.163
2048.0 2048.0  0.0    0.0   12800.0  12800.0   34304.0    33963.1   41392.0 38510.8 5552.0 4952.2     36    0.152  23      3.003    3.155
2048.0 2048.0  0.0    0.0   12800.0  12800.0   34304.0    33948.6   41392.0 38510.8 5552.0 4952.2     36    0.152  30      4.007    4.159
2048.0 2048.0  0.0    0.0   12800.0  12800.0   34304.0    33936.1   41392.0 38510.8 5552.0 4952.2     36    0.152  37      5.038    5.190

可以看到开启了 Adaptive Size Policy 后，堆内存大小进行了变化，例如 Eden 区由 12800 -> 8704 -> 5632

而关闭后，各个区域的空间没有变化

GC 中的 Ergonomics 到底是因为什么

所以 GC logs 中 Ergonomics 产生的 GC 是因为什么呢？

其实是两类都有，也就是说 GC logs 这里展示的 Ergonomics 存在歧义，有一个 Issue 正是和这个问题相关

JDK-8067243 GC reason "Ergonomics" confusing - Java Bug System (openjdk.org)

In this case the reason Ergonomics really mean "Not enough old space to handle next yc given the historical promotion rate", which does not necessarily indicate a Full GC triggered by the resizing of the heap.

It would be great if we could be more specific about why we garbage collect, so that the information can be actionable without reading the HotSpot source code. After discussions with Jesper, a better name would probably be "Out of Old Space" possible with the addtion " for next YC".

关闭了堆内存自动优化后，Ergonomics 的真正含义其实就变成了空间担保

这里 Issue 的发起者也提供了一个更直观的表达 Out of Old Space + for next YC

不过看起来这个 Issue 还是开启状态

参考

Java Garbage Collection Logs & How to Analyze Them - Sematext

看懂gc日志 | LearnJava (gitbook.io)

Universal JVM GC analyzer - Java Garbage collection log analysis made easy (ycrash.cn)

java - Full Garbage Collection vs. Major Garbage Collection - Stack Overflow

Ergonomics (oracle.com)