Kyle's Notebook

JVM GC 日志分析

Word count: 3.2kReading time: 15 min
2020/02/01

写于肺炎疫情爆发、宅在家 10 天后的二月第一天,顺便纪念第三个被炸的微博号,Fuck you Sina Weibo!

JVM GC 日志分析

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 的数组

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
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:

image-20200202120351560

最后:

image-20200202120520819

运行:

1
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

日志解析

输出日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
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 版本,发行时间,运行的平台、页大小、物理内存、交换空间的最大值和空闲值等。

1
2
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 的配置参数,在上一节已有说明。

1
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)。

1
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;

  • 元空间与类空间(存放类信息、常量池等)的使用情况,总容量、使用内存等。

1
2
3
4
5
6
7
8
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 的数组。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
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)。

image-20200202122156522

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

image-20200202122457076

最后:

image-20200202122707703

运行:

1
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

输出日志如下(省略部分):

1
2
3
4
5
6
7
8
9
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)。

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

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

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

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

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

测试代码 2

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
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 数组与前面图示相同,此处不再赘述。

image-20200202124135125

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

image-20200202124847257

最后:

image-20200202125055198

日志解析 2

输出日志如下(省略部分):

1
2
3
4
5
6
7
8
9
10
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 区被清理完。

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

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

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

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

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

1
2
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,被认为是大对象):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
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,由于占用内存大于阈值,直接分配到老年代:

image-20200202125424292

(注意此处 array1 已经置为 null,忘记改成虚线了)创建 array2 ~ array5,直接在 Eden 区分配内存:

image-20200202125744738

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

  • 首先在 Young GC 会把两个 2MB 数组迁入老年代;

  • 无法继续往迁入一个 2MB、一个 128KB 的数组,因此触发 Full GC(清理 4MB 数组);

  • 最后在 Eden 为 array6 分配内存。

image-20200202131029766

image-20200202131229114

运行:

1
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

日志解析

输出日志如下(省略部分):

1
2
3
4
5
6
7
8
9
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 占用不降反升,因为几个对象全部都被引用,无法回收。

1
[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)。

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

并触发一次元空间的 GC:

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

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

1
eden space 8192K,  27% used [0x00000000fec00000, 0x00000000fee297a8, 0x00000000ff400000)
CATALOG
  1. 1. JVM GC 日志分析
    1. 1.1. Young GC:GC 后对象进入 Survivor
      1. 1.1.1. JVM 参数
      2. 1.1.2. 测试代码
      3. 1.1.3. 日志解析
    2. 1.2. Young GC:GC 后进入老年代
      1. 1.2.1. JVM 参数
      2. 1.2.2. 测试代码 1
      3. 1.2.3. 日志解析 1
      4. 1.2.4. 测试代码 2
      5. 1.2.5. 日志解析 2
    3. 1.3. Full GC:GC 后对象进入老年代
      1. 1.3.1. JVM 参数
      2. 1.3.2. 测试代码
      3. 1.3.3. 日志解析