JVM GC 日志分析 #59

kyle-ip · 2023-06-08T01:57:39Z

kyle-ip
Jun 8, 2023
Maintainer

Young GC：GC 后对象进入 Survivor

当为对象分配内存时 Eden 不足，触发 Young GC，清理垃圾并把存活对象迁入 To Survivor。

JVM 参数

序号	参数	备注
1	-XX:NewSize=5242880 -XX:MaxNewSize=5242880	新生代初始值和最大值：5MB
2	-XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760	堆初始值和最大值：10MB
3	-XX:PretenureSizeThreshold=10485760	进入老年代的对象内存阈值：10MB
4	-XX:SurvivorRatio=8	新生代 Eden 占比（Eden 80% 即 4MB，Survivor 各 10% 即 0.5 MB）
5	-XX:+UseParNewGC	使用 ParNew 收集器（新生代）
6	-XX:+UseConcMarkSweepGC	使用 CMS 收集器
7	-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log	输出日志

测试代码

分配三个 byte 数组，每个都是 1024 * 1024 byte == 1MB，再分配一个 2MB 的数组

public class Demo {
    
    private final static Integer MB = 1024 * 1024;
    
    public static void main(String[] args) {

        // 分配三个数组，每个都是 1MB，并置为 null
        byte[] array1 = new byte[MB];
        array1 = new byte[MB];
        array1 = new byte[MB];
        array1 = null;

        // 此时前三个已经变成垃圾，Eden 剩余 4 - 3 == 1MB，无法存放 2MB 对象，触发 Young GC
        byte[] array2 = new byte[2 * MB];
    }
}

先分配三个数组（array1），每个都是 1MB，并置为 null（在下次 GC 时会被清理）。

当为 array2 分配 2MB 内存时，Eden 区不足，先触发 Young GC：

最后：

运行：

java -jar -XX:NewSize=5242880 -XX:MaxNewSize=5242880 -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log Demo.jar

日志解析

输出日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for windows-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 04:01:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16658532k(7782036k free), swap 17707108k(3801772k free)
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
0.113: [GC (Allocation Failure) 0.114: [ParNew: 3892K->440K(4608K), 0.0011414 secs] 3892K->1466K(9728K), 0.0018413 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 4608K, used 3674K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  78% used [0x00000000ff600000, 0x00000000ff928650, 0x00000000ffa00000)
  from space 512K,  86% used [0x00000000ffa80000, 0x00000000ffaee310, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 1026K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3322K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

以上日志分为三个部分：

第一部分为 JVM 的基本信息，包括 JVM 版本，JRE 版本，发行时间，运行的平台、页大小、物理内存、交换空间的最大值和空闲值等。

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for windows-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 04:01:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16658532k(7782036k free), swap 17707108k(3801772k free)

第二部分为 JVM 的配置参数，在上一节已有说明。

CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC

第三部分提示堆内存分配失败（Allocation Failure）、触发 GC：

系统运行了 0.113s 后 Eden 分配失败，触发 Young GC，需要使用 ParNew 收集器回收新生代代；
新生代代可用空间为 4608KB（即 Eden + From Survivor 的空间，共 4.5MB）；
GC 前占用 3892K，GC 后剩余 440K 对象存活，被迁入 To Survivor；
本次 GC 耗费 0.0011414s，回收前堆占用 3892K，回收后堆占用 1466K，总可用空间 9728K（包括新生代代 4.5MB + 老年代 5MB）；
最后提示本次 GC 消耗的时间：用户态 CPU 时间 0.00、内核态 CPU 时间 0.00、墙钟时间 0.00（包括各种非运算的等待耗时，如 IO 等待、线程阻塞）。

需要注意的是代码中分配 3MB的数组（即 3072KB），实际占用 3892KB，因为除了存储数组还附带其他元信息，以及一些“其他对象”（将会被迁到 To Survivor）。

0.113: [GC (Allocation Failure) 0.114: [ParNew: 3892K->440K(4608K), 0.0011414 secs] 3892K->1466K(9728K), 0.0018413 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

第四部分是 JVM 退出前堆具体使用情况：

新生代代共 4608KB 可用内存，使用了 3674 KB；
Eden、From Survivor、To Survivor 占用空间与内存地址
使用 CMS 收集器，管理老年代共 5120KB，此时使用 1026KB；
元空间与类空间（存放类信息、常量池等）的使用情况，总容量、使用内存等。

Heap
 par new generation   total 4608K, used 3674K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  78% used [0x00000000ff600000, 0x00000000ff928650, 0x00000000ffa00000)
  from space 512K,  86% used [0x00000000ffa80000, 0x00000000ffaee310, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 1026K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3322K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

Young GC：GC 后进入老年代

触发 Young GC 清理垃圾，对于存活时间足够长的对象迁入老年代。

JVM 参数

参考上面章节，其中有以下改动：

序号	参数	备注
1	-XX:NewSize=10485760 -XX:MaxNewSize=10485760	新生代初始值和最大值：10MB
2	-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520	堆初始值和最大值：20MB
3	-XX:PretenureSizeThreshold=10485760	进入老年代的对象内存阈值：10MB
4	-XX:MaxTenuringThreshold=15	进入老年代的对象年龄阈值：15

因此 Eden 改为 8MB，Survivor 各 1MB，老年代 10MB，堆共 20MB。

测试代码 1

分配三个 byte 数组，每个都是 2MB，再分配一个 128KB 的数组、一个 2MB 的数组。

public class Demo {
    
    public static void main(String[] args) {

        // 分配三个数组，每个都是 2MB
        byte[] array1 = new byte[2 * 1024 * 1024];
        array1 = new byte[2 * 1024 * 1024];
        array1 = new byte[2 * 1024 * 1024];
        array1 = null;

        byte[] array2 = new byte[128 * 1024];
        
        // 由于以上代码已占用 Eden 区 6.125MB，不足与再为 array3 分配内存，因此触发 GC
        byte[] array3 = new byte[2 * 1024 * 1024];
    }
}

先分配三个数组（array1），每个都是 2MB，并置为 null（在下次 GC 时会被清理），再分配一个 128KB 的数组（array2）。

当为 array3 分配 2MB 内存时，Eden 区不足，先触发 Young GC：

最后：

运行：

java -jar -XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10485760 -XX:MaxTenuringThreshold=15 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log Demo.jar

日志解析 1

输出日志如下（省略部分）：

0.387: [GC (Allocation Failure) 0.387: [ParNew: 7690K->537K(9216K), 0.0013235 secs] 7690K->537K(19456K), 0.0015702 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 2749K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee290e0, 0x00000000ff400000)
  from space 1024K,  52% used [0x00000000ff500000, 0x00000000ff586528, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 0K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3000K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 333K, capacity 388K, committed 512K, reserved 1048576K

先从代码的角度分析：

array1 的创建与三次赋值，在 Eden 区创建了三个 2MB 的数组，最后设置为 null，因此 Eden 此时占用 6MB、空闲 2MB；
创建 array2 占用 128KB，此时 Eden 占用 6.125MB，空闲 1.875MB；
创建 array3 占用 2MB，Eden 区空间不足，此时触发 Young GC。

在 GC 之前新生代代占用 7690KB，即 array1 + array2 + “其他对象”，清理后剩余 537KB（即新生代代最初创建的“其他对象”，再加上 128KB 的 array2）。

[ParNew: 7690K->537K(9216K), 0.0013235 secs]

此时剩余 From Survivor 占用 52%，经历一次 Young GC 后存活的 array2 和“其他对象”，此时他们 1 岁。

  from space 1024K,  52% used [0x00000000ff500000, 0x00000000ff586528, 0x00000000ff600000)

此时 Eden 区占用 27% 约 2MB，即经历 Young GC 后分配的 array3。

  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee290e0, 0x00000000ff400000)

测试代码 2

补充代码：在上述基础上，再继续分配内存，再让 array3 指向 null；当为 array4 分配 2MB 内存时将 Eden 会不足，触发 GC。

public class Demo {
    public static void main(String[] args) {
		byte[] array1 = new byte[2 * 1024 * 1024];
        array1 = new byte[2 * 1024 * 1024];
        array1 = new byte[2 * 1024 * 1024];
        array1 = null;

        byte[] array2 = new byte[128 * 1024];
        byte[] array3 = new byte[2 * 1024 * 1024];

        array3 = new byte[2 * 1024 * 1024];
        array3 = new byte[2 * 1024 * 1024];
        array3 = new byte[128 * 1024];
        array3 = null;

        // 此时分配一个 2MB 的数组失败，触发第二次 Young GC
        byte[] array4 = new byte[2 * 1024 * 1024];
    }
}

对于为 array3 继续分配 2MB 数组与前面图示相同，此处不再赘述。

创建 array4 前发现空间不足，触发 Young GC：由于 array2 和“其他对象”都“太老了”，被迁入老年代：

最后：

日志解析 2

输出日志如下（省略部分）：

0.118: [GC (Allocation Failure) 0.118: [ParNew: 8185K->606K(9216K), 0.0005936 secs] 8185K->606K(19456K), 0.0007441 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.119: [GC (Allocation Failure) 0.119: [ParNew: 6907K->0K(9216K), 0.0021618 secs] 6907K->570K(19456K), 0.0022048 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 2130K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  26% used [0x00000000fec00000, 0x00000000fee14930, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
 concurrent mark-sweep generation total 10240K, used 570K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3344K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 369K, capacity 388K, committed 512K, reserved 1048576K

第一次 GC 分析同上，重点看第二次 GC 日志：经过一次 Young GC 后，Eden 区被清理完。

[ParNew: 6907K->0K(9216K), 0.0021618 secs]

由于年龄 1 + 年龄 2 +...+ 年龄 n 的对象总大小超过了 Survivor 区的 50%，年龄 n 以上就会进入老年代

此处总大小超过 50% 的年龄 1 对象（array2、“其他对象”）会直接进入老年代。

 concurrent mark-sweep generation total 10240K, used 570K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)

由于 GC 过后对象被迁入老年代，所以两个 Survivor 都是空的：

  from space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)

Full GC：GC 后对象进入老年代

JVM 参数

序号	参数	备注
1	-XX:NewSize=10485760 -XX:MaxNewSize=10485760	新生代初始值和最大值：10MB
2	-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520	堆初始值和最大值：20MB
3	-XX:PretenureSizeThreshold=3145728	进入老年代的对象内存阈值：3MB
4	-XX:MaxTenuringThreshold=15	进入老年代的对象年龄阈值：15
4	-XX:SurvivorRatio=8	新生代 Eden 占比（Eden 80% 即 4MB，Survivor 各 10% 即 0.5 MB）
5	-XX:+UseParNewGC	使用 ParNew 收集器（新生代）
6	-XX:+UseConcMarkSweepGC	使用 CMS 收集器
7	-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log	输出日志

主要是降低进入老年代的对象内存阈值，使超过 3MB 的对象直接进入老年代。

测试代码

创建多个数组（其中 array1 为 4MB，被认为是大对象）：

public class Demo {
    
    public static void main(String[] args) {
        byte[] array1 = new byte[4 * 1024 * 1024];
        array1 = null;

        byte[] array2 = new byte[2 * 1024 * 1024];
        byte[] array3 = new byte[2 * 1024 * 1024];
        byte[] array4 = new byte[2 * 1024 * 1024];
        byte[] array5 = new byte[128 * 1024];

        byte[] array6 = new byte[2 * 1024 * 1024];
    }
}

创建 array1，由于占用内存大于阈值，直接分配到老年代：

（注意此处 array1 已经置为 null，忘记改成虚线了）创建 array2 ~ array5，直接在 Eden 区分配内存：

创建 array6 时 Eden 不足，触发 Young GC。但由于 Survivor 不足、老年代也不足，因此还需要触发 Full GC。

首先在 Young GC 会把两个 2MB 数组迁入老年代；
无法继续往迁入一个 2MB、一个 128KB 的数组，因此触发 Full GC（清理 4MB 数组）；
最后在 Eden 为 array6 分配内存。

运行：

java -jar -XX:NewSize=10485760 -XX:MaxNewSize=10485760 -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=15 -XX:PretenureSizeThreshold=3145728 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log Demo.jar

日志解析

输出日志如下（省略部分）：

0.114: [GC (Allocation Failure) 0.114: [ParNew (promotion failed): 8185K->8752K(9216K), 0.0037134 secs]0.118: [CMS: 8194K->6680K(10240K), 0.0030624 secs] 12281K->6680K(19456K), [Metaspace: 3323K->3323K(1056768K)], 0.0071795 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 9216K, used 2213K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee297a8, 0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 concurrent mark-sweep generation total 10240K, used 6680K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3344K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 369K, capacity 388K, committed 512K, reserved 1048576K

首先为 array1 分配了 4MB 的数组，被认为是大对象、直接进入老年代（剩余 10 - 4 == 6MB），随后不再引用；

再连续分配 4 个数组 array2 ~ array5 到 Eden 区，Eden 区占用 6.125MB、剩余 1.875MB；由于剩余空间不足以为 array6 分配 2MB 内存，此时触发 Young GC。

可见 GC 后 Eden 占用不降反升，因为几个对象全部都被引用，无法回收。

[ParNew (promotion failed): 8185K->8752K(9216K), 0.0037134 secs]

此时无法直接把这些对象（3 个 2MB、1 个 128KB）迁入老年代（剩余 6MB），因此触发 Full GC：

先往老年代迁入 2 个 2MB 数组，剩余空间不足；
触发 Full GC，回收前面已经置为 null 的 array1；
迁入剩余 1 个 2MB 数组和 1个 128KB 数组（因此从回收前的 8MB 变成 6MB）。

[CMS: 8194K->6680K(10240K), 0.0030624 secs] 12281K->6680K(19456K)

并触发一次元空间的 GC：

[Metaspace: 3323K->3323K(1056768K)]

由于 Full GC 后新生代代对象已迁入老年代，最后在 Eden 为 array6 分配 2MB。

  eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee297a8, 0x00000000ff400000)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

JVM GC 日志分析 #59

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 0 comments

Select a reply

Uh oh!

JVM GC 日志分析 #59

Uh oh!

Uh oh!

kyle-ip Jun 8, 2023 Maintainer

Young GC：GC 后对象进入 Survivor

JVM 参数

测试代码

日志解析

Young GC：GC 后进入老年代

JVM 参数

测试代码 1

日志解析 1

测试代码 2

日志解析 2

Full GC：GC 后对象进入老年代

JVM 参数

测试代码

日志解析

Replies: 0 comments

kyle-ip
Jun 8, 2023
Maintainer