本文用于记录在学习 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.

常用垃圾收集器参数

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

实验代码

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 区分配

实验结果：

[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 区分配

实验结果

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.

实验结果：

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来设置进入老年代的对象年龄

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

实验结果：

[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

[图片上传失败...(image-892112-1512046822615)]

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

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

实验结果

[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

[图片上传失败...(image-a56ba8-1512046822615)]

实验分析

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

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

实验六：TenuringThreshold 是动态变化的

实验结果

[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值一直在变化也能得到验证。