20_模拟 JVM 的 Young GC 场景

约 1659 字大约 6 分钟

2024-08-10

我们动手模拟下 Young GC 的场景，结合 GC 日志去分析 JVM 到底是怎样运行的

参数配置

下面这些参数基于 JDK1.8 版本来配置的，忘记怎么设置的可以回看 07_动手实验：系统部署时如何设置JVM内存大小 的内容

//初始新生代大小 最大新生代大小    初始堆内存大小           最大堆内存大小       Eden区占比新生代比例 大对象阈值                      新生代垃圾器 ParNew 老年代垃圾器 CMS      打印详细 GC 日志     打印每次发生GC的时间    将GC 日志写入磁盘文件
-XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log

模拟代码

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

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

上面代码通过 new byte[1024 * 1024] 连续分配了 3 个 1MB 数组，array1 这个局部变量依次引用这三个对象，最后 array1 指向 null

在我们配置的 JVM 参数中，新生代大小为 5M，Eden 区大小为 4M，当给 array2 局部变量分配 2MB 大小数组时，显然 Eden 区已放不下了，如下图所示，此时就会发生 Young GC

GC 日志分析

执行代码之后在当前项目下会有一个 gc.log 文件，内容如下，我们一点一点分析如何看日志

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 25038040k(8306556k free), swap 47862644k(23664868k 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.169: [GC (Allocation Failure) 0.169: [ParNew: 3660K->0K(4608K), 0.0120803 secs] 4289K->1138K(9728K), 0.0121267 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1138K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3342K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

一次 GC 的概要说明

0.169: [GC (Allocation Failure) 0.169: [ParNew: 3660K->0K(4608K), 0.0120803 secs] 4289K->1138K(9728K), 0.0121267 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

GC (Allocation Failure)：发生 GC 的原因（分配失败），分配 2MB 内存大小数组时，但是 Eden 区内存不够了
0.169：系统运行多少秒发生的本次 GC
ParNew: 3660K->0K(4608K), 0.0120803 secs
- ParNew：使用指定的 ParNew 垃圾回收器执行 GC，触发的是 Young GC
- 3660K->0K(4608K)：年轻代可以用空间是 4608K（4.5MB），Eden区 4MB + Survivor 0.5MB
- 0.0120803 secs：本次 GC 耗费秒数
4289K->1138K(9728K), 0.0121267 secs
- 9728K：整个 Java堆内存 总可用空间 9728K（9.5MB），年轻代 4.5MB + 老年代 5MB
- 4289K：GC 前 Java堆内存 使用了 4289K，GC 之后 Java堆内存 使用了 1138K
[Times: user=0.00 sys=0.00, real=0.01 secs]：本次 GC 耗时，单位为秒

3660K->0K(4608K), 0.0120803 secs，在 Eden 区我们就放了 3 个 1MB 的数组，一共是 3072KB（3MB），为什么日志显示 GC 之前年轻代使用了 3660KB 呢？

1、创建的数组本身是 1MB，但是为了存储这个数组，JVM 内置还会附带一些其他信息，所以每个数组实际占用内存是大于 1MB 的
2、除了自己创建的对象外，可能还有一些其他对象在 Eden 区，后面可以用专门的工具分析堆内存快照，看到这些其他对象

GC 过后的堆内存使用情况

Heap
 par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1138K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3342K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

这段日志是 JVM 退出时候打印的当前堆内存使用情况

par new generation total 4608K, used 2089K：ParNew 垃圾回收器负责的年轻代总共有 4608K（4.5MB） 可用内存，目前使用了 2089K（2MB），这 2MB 是我们代码最后创建的数组
eden space 4096K, 51% used：Eden 区的 4MB 内存被使用了 51%
from、to：表示两个 Survivor 的使用情况
concurrent mark-sweep generation total 5120K, used 1138K：CMS（concurrent mark-sweep） 垃圾回收器管理的老年代空间一共是 5MB，此时使用了 1138KB
Metaspace、class space：Metaspace元数据空间和 Class 空间，存放类信息、常量池之类的，此时他们的总容量、使用内存等信息

模拟时出现的意外情况

在前面的分析中，我们执行的代码只会发生一次 Young GC，但是在实际的 GC 日志中看到有两次，日志如下

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 25038040k(8306556k free), swap 47862644k(23664868k 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.167: [GC (Allocation Failure) 0.167: [ParNew: 3251K->512K(4608K), 0.0020524 secs] 3251K->1141K(9728K), 0.0021564 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.169: [GC (Allocation Failure) 0.169: [ParNew: 3660K->0K(4608K), 0.0120803 secs] 4289K->1138K(9728K), 0.0121267 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
  from space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
  to   space 512K,   0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
 concurrent mark-sweep generation total 5120K, used 1138K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3342K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 365K, capacity 388K, committed 512K, reserved 1048576K

实际上，执行 main 方法也会占用内存空间，我们做如下测试，只创建 1 个 1MB 的数组，也发生了一次 GC

public static void main(String[] args) {
    byte[] array1 = new byte[1024 * 1024];
}

Java HotSpot(TM) 64-Bit Server VM (25.92-b14) for windows-amd64 JRE (1.8.0_92-b14), built on Mar 31 2016 21:03:04 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 25038040k(8474452k free), swap 47862644k(23219700k 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 
5.205: [GC (Allocation Failure) 5.227: [ParNew: 3153K->512K(4608K), 0.0443193 secs] 3153K->1112K(9728K), 0.0671418 secs] [Times: user=0.00 sys=0.00, real=0.07 secs] 
Heap
 par new generation   total 4608K, used 1701K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  29% used [0x00000000ff600000, 0x00000000ff7296b8, 0x00000000ffa00000)
  from space 512K, 100% used [0x00000000ffa80000, 0x00000000ffb00000, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 600K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3244K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 359K, capacity 388K, committed 512K, reserved 1048576K