JVM-探究（二）：JVM实验和 GC 日志解读

技术
, ,

本文用于记录在学习 JVM 过程中的实验，在完成《深入理解Java虚拟机》第二版第三章中的实验的基础上，同时保证在JDK1.8上实验的可重复性，并且针对不同的垃圾收集器做实验扩充。在对不能在JDK8上重现的实验代码做了修正，在实验结果中分析了JVM的部分特性, 介绍了GC日志的解读等。

GC 日志含义

GC 日志理解起来十分简单，因为日志本来就是要给开发人员看的，所以设计的很直观。

举个例子，我们来分别说明各个部分所代表的含义：

[GC (Allocation Failure) [ParNew: 7989K->424K(9216K), 0.0037834 secs] 7989K->6568K(19456K), 0.0038147 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

将上面 GC 日志抽象为各个部分，然后我们再分别说明各个部分的含义

[a(b)[c:d->e(f), g secs] h->i(j), k secs] [Times: user:l sys=m, real=n secs]

a: GC 或者是 Full GC， 这里引用一句话

“GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有“Full”，说明这次GC是发生了Stop-The-World的”

摘录来自: 周志明. “深入理解Java虚拟机：JVM高级特性与最佳实践（第2版）”。 iBooks.

b: 用来说明发生这次 GC 的原因，我们例子中发生这次GC的原因是内存分配失败

c: 表示发生GC的区域，这里表示是新生代发生了GC，上面那个例子是因为在新生代中内存不够给新对象分配了，然后触发了 GC

d: GC 之前该区域已使用的容量

e: GC 之后该区域已使用的容量

f: 该内存区域的总容量

g: 表示该区域这次 GC 使用的时间

h: 表示 GC 前整个堆的已使用容量

i: 表示 GC 后整个堆的已使用容量

j: 表示 Java 堆的总容量

k: 表示 Java堆 这次 GC 使用的时间

l: 代表用户态消耗的 CPU 时间

m: 代表内核态消耗的 CPU 时间

n: 整个 GC 事件从开始到结束的墙钟时间（Wall Clock Time）

“CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。”

摘录来自: 周志明. “深入理解Java虚拟机：JVM高级特性与最佳实践（第2版）”。 iBooks.

名词解释

“**新生代GC（Minor GC)**：指发生在新生代的垃圾收集动作，因为Java对象大多都具备朝生夕灭的特性，所以Minor GC非常频繁，一般回收速度也比较快。

老年代GC（Major GC/Full GC）：指发生在老年代的GC，出现了Major GC，经常会伴随至少一次的Minor GC（但非绝对的，在Parallel Scavenge收集器的收集策略里就有直接进行Major GC的策略选择过程）。Major GC的速度一般会比Minor GC慢10倍以上。”

摘录来自: 周志明. “深入理解Java虚拟机：JVM高级特性与最佳实践（第2版）”。 iBooks.

常用垃圾收集器参数

参数 描述
UseSerialGC 虚拟机在运行在 Client 模式下的默认值，打开此开关后，使用 Serial+Serial Old 收集器组合进行内存回收
UseParNewGC 使用 ParNew + Serial Old 收集器组合进行内存回收
UseConcMarkSweepGC 使用 ParNew + CMS + Serial Old 的收集器组合进行内存回收，当 CMS 出现 Concurrent Mode Failure 失败后会使用 Serial Old 作为备用收集器
UseParallelOldGC 使用 Parallel Scavenge + Parallel Old 的收集器组合
UseParallelGC 使用 Parallel Scavenge + Serial Old （PS MarkSweep）的收集器组合
SurvivorRatio 新生代中 Eden 和任何一个 Survivor 区域的容量比值，默认为 8
PretenureSizeThreshold 直接晋升到老年代对象的大小，单位是Byte
MaxTenuringThreshold 晋升到老年代的对象最大年龄
UseAdaptiveSizePolicy 动态调整 Java 堆中各区域的大小以及进入老年代的年龄
HandlePromotionFailure 是否允许分配担保失败
ParallelGCThreads 设置并行 GC 时进行内存回收的线程数
GCTimeRatio GC 时间站占时间的比率，默认值为99，只在 Parallel Scavenge 收集器的时候生效
MaxGCPauseMillis 设置 GC 最大的停顿时间，只在 Parallel Scavenge 收集器的时候生效
CMSInitiatingOccupancyFraction 设置 CMS 收集器在老年代空间被使用多少后触发垃圾收集，默认是 68%，仅在 CMS 收集器上生效
CMSFullGCsBeforeCompaction 设置 CMS 收集器在进行多少次垃圾回收之后启动一次内存碎片整理

注：上表摘录来自: 周志明. “深入理解Java虚拟机：JVM高级特性与最佳实践（第2版）”，稍有调整.

实验代码

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
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
package com.coderbean.jvm;

/**
 * Created by jacobchang on 2017/11/20.
 *
 */
public class TestAllocation {
    private static final int _1MB = 1024*1024;
    /**
     * VM参数：（参数序号对应实验序号）
     *  1. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     *  2. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     */
    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2*_1MB];
        allocation2 = new byte[2*_1MB];
        allocation3 = new byte[2*_1MB];
        allocation4 = new byte[4*_1MB]; //出现一次 Minor GC
    }

    /**
     * VM参数：（参数序号对应实验序号）
     *  3. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:PretenureSizeThreshold=3145728
     */
    public static void testPreteureSizeThreshold() {
        byte[] allocation;
        allocation = new byte[4 * _1MB];
    }

    /**
     * VM参数：（参数序号对应实验序号）
     *  4. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -XX:MaxTenuringThreshold=1 -XX:+PrintTenuringDistribution
     *  5. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -XX:MaxTenuringThreshold=4 -XX:+PrintTenuringDistribution
     *
     */
    @SuppressWarnings("unused")
    public static void testTenuringThredhold() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[_1MB / 16];
        allocation3 = new byte[4 * _1MB];
        allocation4 = new byte[4 * _1MB];
        allocation4 = null;
        allocation4 = new byte[4 * _1MB];
    }

    /**
     * VM参数：（参数序号对应实验序号）
     *  6. -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseSerialGC -XX:+PrintGCDetails -XX:MaxTenuringThreshold=4 -XX:+PrintTenuringDistribution
     *
     *  如果在Survivor空间中相同年龄所有对象大小的总和>Survivor空间的一半（ -XX:TargetSurvivorRatio）时，年龄>=该年龄的对象就可以直接进入年老代
     */
    @SuppressWarnings("unused")
    public static void testTenuringThredhold2() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[_1MB / 4];
        allocation3 = new byte[4 * _1MB];
        allocation4 = new byte[4 * _1MB];
        allocation4 = null;
        allocation4 = new byte[4 * _1MB];
    }
}


实验

实验一：使用ParNew+Serial Old的组合进行内存回收

对象优先在 Eden 区分配

实验结果：

1
2
3
4
5
6
7
8
9
10
11
12
[GC (Allocation Failure) [ParNew: 7989K->424K(9216K), 0.0037834 secs] 7989K->6568K(19456K), 0.0038147 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
Heap
 par new generation   total 9216K, used 4685K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf0290f0, 0x00000007bf400000)
  from space 1024K,  41% used [0x00000007bf500000, 0x00000007bf56a3a8, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 tenured generation   total 10240K, used 6144K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  60% used [0x00000007bf600000, 0x00000007bfc00030, 0x00000007bfc00200, 0x00000007c0000000)
 Metaspace       used 3242K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 359K, capacity 388K, committed 512K, reserved 1048576K

Process finished with exit code 0

实验分析：

通过上面的GC日志我们可以看出一开始出现了 MinorGC, 引起GC的原因是 内存分配失败，因为分配allocation4的时候，Eden区已经没有足够的区域来分配了，所以发生了本次 MinorGC ，经过 MinorGC 之后新生代的已使用容量从7989K减少到了424K，然而整个堆的内存总量却几乎没有减少，原因就是，由于发现新生代没有可以回收的对象，所以不得不使用内存担保将allocation1～3 三个对象提前转移到老年代。此时再在 Eden 区域为 allocation4 分配 4MB 的空间，因此最后我们发现 Eden 区域占用了 4MB，老年代占用了 6MB

实验二：使用Parallel Scavenge+Serial Old的组合进行内存回收

对象优先在 Eden 区分配

实验结果

1
2
3
4
5
6
7
8
9
Heap
PSYoungGen      total 9216K, used 8192K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 eden space 8192K, 100% used [0x00000007bf600000,0x00000007bfe00000,0x00000007bfe00000)
 from space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
 to   space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
ParOldGen       total 10240K, used 4096K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
 object space 10240K, 40% used [0x00000007bec00000,0x00000007bf000010,0x00000007bf600000)
Metaspace       used 3311K, capacity 4496K, committed 4864K, reserved 1056768K
 class space    used 369K, capacity 388K, committed 512K, reserved 1048576K

实验分析

第一眼看到日志惊奇的发现居然没有发生任何类型的 GC， 起初看到日志的时候我也很惊奇，于是乎请出了Java内存分析工具VisualVM, JDK中会自带JVisualVM 效果类似，可以通过命令jvisualvm启动，具体分析方法可以参考我的另外一篇博客VisualVM使用指南。

注： 如果想要重现下面的分析结果，除了JVM参数要和我一直外，在程序执行过程中务必设置几个断点，好让VisualVM能够出现这种阶梯图像，不然由于执行太快，看起来就像是一次性分配了内存一样。

堆内存占用情况分析

通过上图中我标出的五条线，可以看到在1位置的时候第一次在Eden中分配了 2MB 内存，然后在2，3，4 时刻分别又再次分配了 2MB 内存，此时 Eden 区域已经占用了 8MB 了，在 5 时刻当要分配 4MB 内存的时候，Eden 区域已经不够用了，直接分配到了老年代。这是因为Parallel Scavenge收集器为了保证吞吐量而直接将Eden区中无法存放的大对象直接放到了老年代。

注： 虚拟机参数 -XX：PretenureSizeThreshold 并不是实验二中的大对象分配到老年代的直接控制参数，该参数只针对 Serial 和 ParNew 两个新生代收集器有作用。 该参数的作用在下一节大对象直接进入老年代的实验中讲解。

使用其他收集器组合探究对象的分配情况

由于篇幅有限，其实是我想偷懒了（＾∇＾），各位可以参考上面的垃圾收集器参数章节，自己去验证。

实验三：使用参数-XX:PretenureSizeThreshold来设置直接进入老年代的对象的大小

大对象直接进入老年代
虚拟机提供一个参数 -XX:PretenureSizeThreshold 用来设置直接在老年代分配的对象的大小，如果对象大于这个值就会直接在老年代分配。这样做的目的是避免在Eden区及两个Survivor区之间发生大量的内存复制。

“比遇到一个大对象更加坏的消息就是遇到一群“朝生夕灭”的“短命大对象”，写程序的时候应当避免”

摘录来自: 周志明. “深入理解Java虚拟机：JVM高级特性与最佳实践（第2版）”。 iBooks.

实验结果：

1
2
3
4
5
6
7
8
9
10
Heap
 par new generation   total 9216K, used 2936K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  35% used [0x00000007bec00000, 0x00000007beede130, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 tenured generation   total 10240K, used 4096K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  40% used [0x00000007bf600000, 0x00000007bfa00010, 0x00000007bfa00200, 0x00000007c0000000)
 Metaspace       used 3278K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 364K, capacity 388K, committed 512K, reserved 1048576K

实验分析

通过上面的堆的内存占用情况很容易看出我们分配的4MB大小的对象直接被放到了老年代

实验四： 使用参数-XX:MaxTenuringThreshold=1来设置进入老年代的对象年龄

长期存活的对象将进入老年代

实验结果：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 1 (max 1)
- age   1:     749112 bytes,     749112 total
: 6868K->731K(9216K), 0.0039484 secs] 6868K->4827K(19456K), 0.0039697 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 1 (max 1)
- age   1:       1496 bytes,       1496 total
: 4911K->1K(9216K), 0.0012023 secs] 9007K->4706K(19456K), 0.0012150 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 9216K, used 4316K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf036cc8, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf4005d8, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 tenured generation   total 10240K, used 4704K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  45% used [0x00000007bf600000, 0x00000007bfa98328, 0x00000007bfa98400, 0x00000007c0000000)
 Metaspace       used 3288K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 364K, capacity 388K, committed 512K, reserved 1048576K

实验4

通过上面的堆内存分配和visualGC的分析图片可以看出，当执行到最后一句话的时候，也就是进行第二次GC的时候，原本在S0区域的一些对象被移动到了老年代，这是因为当发生MinorGC的时候发现该对象的年龄已经到达我们设置的MaxTenuringThreshold值。

实验五： 使用参数-XX:MaxTenuringThreshold=4来设置进入老年代的对象年龄

实验结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 1 (max 4)
- age   1:     749320 bytes,     749320 total
: 6868K->731K(9216K), 0.0040400 secs] 6868K->4827K(19456K), 0.0040616 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 4 (max 4)
- age   1:        808 bytes,        808 total
: 4911K->0K(9216K), 0.0012952 secs] 9007K->4706K(19456K), 0.0013076 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 9216K, used 4315K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf036ca8, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400328, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 tenured generation   total 10240K, used 4706K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  45% used [0x00000007bf600000, 0x00000007bfa988a8, 0x00000007bfa98a00, 0x00000007c0000000)
 Metaspace       used 3282K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 364K, capacity 388K, committed 512K, reserved 1048576K

实验5

实验分析

通过上面的日志和图片，可以看出与实验四不同的是，这里执行到最后的时候S0区域中的对象并没有进入到老年代而是进入了S1区域,因为我们把进入老年代的年龄设置为了4.

注：如果没有按照我的代码写的话，你可能会发现即使把MaxTenuringThreshold设置为了大于1的值，但还是有可能会在一次 GC 之后就进入了老年代，这是因为进入我们设置的只是一个最大值，真正的值可能比这个值更小，是动态变化的，这种情况会在下面的实验中介绍。

实验六：TenuringThreshold 是动态变化的

实验结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 1 (max 4)
- age   1:     948816 bytes,     948816 total
: 7123K->926K(9216K), 0.0065933 secs] 7123K->5022K(19456K), 0.0066172 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
[GC (Allocation Failure) [DefNew
Desired survivor size 524288 bytes, new threshold 4 (max 4)
- age   1:        464 bytes,        464 total
: 5270K->0K(9216K), 0.0013556 secs] 9366K->4900K(19456K), 0.0013708 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 9216K, used 4233K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  51% used [0x00000007bec00000, 0x00000007bf022570, 0x00000007bf400000)
  from space 1024K,   0% used [0x00000007bf400000, 0x00000007bf4001d0, 0x00000007bf500000)
  to   space 1024K,   0% used [0x00000007bf500000, 0x00000007bf500000, 0x00000007bf600000)
 tenured generation   total 10240K, used 4899K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
   the space 10240K,  47% used [0x00000007bf600000, 0x00000007bfac8f38, 0x00000007bfac9000, 0x00000007c0000000)
 Metaspace       used 3315K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 367K, capacity 388K, committed 512K, reserved 1048576K

实验结果

实验分析

看到上面的堆信息可以看到最后from和to两个Survivor区域占用情况都为0，原因就是在allocation1被放到S1区域之后，由于该对象和一些附加信息的和占用了S1区域一半以上的空间，因为此时allocation1对象的年龄为1，所以此时TenuringThreshold的值也就变成了1，在GC的时候进入了老年代。通过上图中VisualGC左下角的TenuringThreshold值一直在变化也能得到验证。