手把手教你如何写出完美的JVM的Young GC

Posted 2022-02-13 JavaEdge.

模拟JVM的Young GC

JVM参数示范(基于JDK 1.8)

用如下JVM参数运行代码：

# 初始新生代大小 5M
-XX:NewSize=5242880
# 最大新生代大小 5M
-XX:MaxNewSize=5242880
# 初始堆大小 10M
-XX:InitialHeapSize=10485760
# 最大堆大小 10M
-XX:MaxHeapSize=10485760
-XX:SurvivorRatio=8
# 大对象阈值是10MB
-XX:PretenureSizeThreshold=10485760
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC

如何打印JVM GC日志？

GC日志打印选型：

-XX:+PrintGCDetils：打印详细gc日志

-XX:+PrintGCTimeStamps：这个参数可以打印出来每次GC发生的时间

-Xloggc:gc.log：这个参数可以设置将gc日志写入一个磁盘文件

加上该参数后，JVM参数如下：

-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

实例

对象是如何分配在Eden

byte[] array1 = new byte[1024 * 1024];

该行会在JVM Eden内放入一个1M数组，同时在main线程的虚拟机栈压入一个main方法栈帧，其栈帧内部有一“arr1”变量，该变量指向Eden的那1M数组：

arr1 = new byte[1024 * 1024];

此时会在Eden创建第二个数组，局部变量指向其。然后第一个数组无人引用，成了垃圾：

byte[] array1 = new byte[1024 * 1024];

在Eden创建第三个数组，同时让arr1指向第三个数组，此时前两个数组都无人引用，都成了垃圾：

arr1 = null;

arr1啥都不指了，导致之前创建的3数组全部变成垃圾：

byte[] arr2 = new byte[2 * 1024 * 1024];

分配一个2MB大小的数组，尝试放入Eden，这时Eden放的下吗？

显然不行，Eden共4M，已放入3个1M数组，只剩1M，所以这时就会触发Y-GC。

采用指定JVM参数运行程序

然后运行即可，运行完后，会出现gc.log文件，即本次程序运行的gc日志：

打开gc.log文件，我们会看到如下所示的gc日志：

这次运行程序的JVM参数，包含：

• 我们自己手动设置的

• 默认的参数设置

  给JVM加个打印gc日志的参数，就可以在此看到JVM默认参数配置

一次GC的路途

0.410: [GC (Allocation Failure) 0.410: [ParNew: 3863K->465K(4608K), 0.0025689 secs] 3863K->1491K(9728K), 0.0029347 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

0.269: [ParNew: 4030K->512K(4608K), 0.0015734 secs] 4030K->574K(9728K), 0.0017518 secs]

[Times: user=0.00 sys=0.00, real=0.00 secs]

概要说明本次GC执行情况:

• GC (Allocation Failure)，看字面意思即可，为啥会发生一次GC呢？

  因为要分配一个2M数组，但Eden内存不足，所以“Allocation Failure”，内存分配失败，所以就要触发一次Y-GC。

那这次GC何时发生？

看一个数字，“0.410”：你的系统运行后，过了多少s发生的本次GC，此处就是系统运行后的410ms发生了GC。

ParNew: 3863K->465K(4608K), 0.0025689 secs

此处触发的是Y-GC，所以用的也就是指定的ParNew来执行GC。

3863K->465K(4608K)

新生代可用空间4608KB，约4.5MB，Eden是4M，两个Survivor只有一个可放存活对象，另外一个必须保持空闲，所以年轻代可用空间是 Eden+1个Survivor=4.5MB。

3863K->465K：对年轻代执行一次GC，GC前使用了3863K，但GC后只有465K对象存活。

GC前，我们在Eden只放了3个1M数组，共3MB，即3072K，那为啥这里显示使用了3863K？

• 自定义创建的数组本身虽是1MB，但为存储该数组，JVM内置还会附带一些其它信息，所以每个数组实际占用的内存是大于1MB的
• 可能还有一些你看不见的对象在Eden里

所以GC前，三个数组+其他未知对象=3863K内存。GC前，我们在Eden只放了3个1M数组，共3MB，即3072K，那为啥这里显示使用了3863K？

• 自定义创建的数组本身虽是1MB，但为存储该数组，JVM内置还会附带一些其它信息，所以每个数组实际占用的内存是大于1MB的
• 可能还有一些你看不见的对象在Eden里

所以GC前，三个数组+其他未知对象=3863K内存。

0.0025689 secs：本次GC耗费时间，看这里来说大概耗费2.5ms，仅回收3MB对象而已。

3863K->1491K(9728K), 0.0029347 secs

整个Java堆内存的情况。整个Java堆内存总可用空间9728K（9.5M）=年轻代4.5MB+老年代5M。

• GC前，整个Java堆内存使用了3863K
• GC后Java堆内存使用了1491K

[Times: user=0.01 sys=0.00, real=0.01 secs]

本次gc消耗的时间，这里最小单位是小数点之后两位，单位是s。

图解GC执行过程

ParNew执行GC，回收掉自定义创建的三个数组，此时因为他们都无人引用，必成垃圾：

ParNew: 4030K->512K(4608K), 0.0015734 secs

gc回收后，从4030K内存使用降低到512K内存使用。即这次gc日志有512KB的对象存活，从Eden区转移到Survivor1区：

GC后的堆内存

Heap
par new generation total 4608K, used 2601K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000) eden space 4096K, 51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)

from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000) to space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)

concurrent mark-sweep generation total 5120K, used 62K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)



Metaspace    used 2782K, capacity 4486K, committed 4864K, reserved 1056768K class space used 300K, capacity 386K, committed 512K, reserved 1048576K

JVM退出时打印的当前堆内存使用情况

ParNew负责的新生代共4608K（4.5MB）可用内存，目前使用2630K（2.5MB）。此时在JVM退出前，为何新生代占了2.5M？GC后，通过如下代码又分配了个2M数组：

byte[] arr2 = new byte[2 * 1024 * 1024];

所以此时在Eden一定会有个 2M数组=2048K，然后上次GC后，在From Survivor存活了个512K未知对象，那么：

$2048KB+512KB=2560KB$

每个数组会额外占据一些内存存放一些自己这个对象的元数据，可认为多出来的70K是数组对象额外使用的内存空间。

Eden日志

Eden此时4M内存被用52%，就因为那2M数组。然后From Survivor区，512K是100%使用率，此时被之前GC后存活下来的512K未知对象占据。

CMS、Metaspace元数据空间和Class空间

Concurrent Mark-Sweep垃圾回收器，即CMS管理的老年代内存空间共5M，此时使用了62K。
Metaspace元数据空间和Class空间，存放一些类信息、常量池之类的东西，此时他们的总容量，使用内存等。