JVM gc日志不符合预期问题排查

根据《深入理解Java虚拟机》代码清单3-5，本地跑一下。

代码如下：

public class GCTest {
    private static final int _1MB = 1024 * 1024;

    /**
     * -Xms20m
     * -Xmx20m
     * -Xmn10m
     * -XX:SurvivorRatio=8
     * -XX:+UseConcMarkSweepGC
     * -XX:+PrintGCDetails
     */
    public static void main(String[] args) {
        byte[] bytes1, bytes2, bytes3, bytes4;
        bytes1 = new byte[2 * _1MB];
        bytes2 = new byte[2 * _1MB];
        bytes3 = new byte[2 * _1MB];
        bytes4 = new byte[4 * _1MB];
    }
}

打印结果如下：

[GC (Allocation Failure) [ParNew: 7035K->763K(9216K), 0.0149886 secs] 7035K->4862K(19456K), 0.0150353 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
Heap
 par new generation   total 9216K, used 7146K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  77% used [0x00000007bec00000, 0x00000007bf23b848, 0x00000007bf400000)
  from space 1024K,  74% used [0x00000007bf500000, 0x00000007bf5befc0, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 concurrent mark-sweep generation total 10240K, used 4098K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 3062K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 327K, capacity 388K, committed 512K, reserved 1048576K

发现不符合理想状况：

• 理想状况应该是在第四个对象分配的时候触发gc，此时方法未退出前面三个对象不可销毁，总占用从7035K降到4862K，不合理。
• 后面的快照中，eden区应该只有第四个对象，占用大小不合理。
• 快照中from区占用不合理，因为大对象直接进入老年代。

猜测可能由于某些原因，并不是在第四个对象分配的时候gc的，将第四个对象注释掉，运行结果如下：

[GC (Allocation Failure) [ParNew: 7035K->770K(9216K), 0.0170803 secs] 7035K->4869K(19456K), 0.0171278 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
Heap
 par new generation   total 9216K, used 2901K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  26% used [0x00000007bec00000, 0x00000007bee14930, 0x00000007bf400000)
  from space 1024K,  75% used [0x00000007bf500000, 0x00000007bf5c0bb0, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 concurrent mark-sweep generation total 10240K, used 4098K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 3068K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 327K, capacity 388K, committed 512K, reserved 1048576K

发现果然是在第三个对象分配的时候gc了，gc掉了2M左右的东西，并且不是程序代码产生的。

考虑到代码是用intellij idea启动的，猜测可能是它所引起。改为使用java命令启动：

➜  classes java -Xms20m -Xmx20m -Xmn10m -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails com/keygen/demo/test/GCTest
[GC (Allocation Failure) [ParNew: 6651K->302K(9216K), 0.0089398 secs] 6651K->6448K(19456K), 0.0089839 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 9216K, used 4562K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  52% used [0x00000007bec00000, 0x00000007bf0290e0, 0x00000007bf400000)
  from space 1024K,  29% used [0x00000007bf500000, 0x00000007bf54b950, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 concurrent mark-sweep generation total 10240K, used 6146K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 2618K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 277K, capacity 386K, committed 512K, reserved 1048576K

情况符合书中结果，总内存占用基本没有降低，且快照中eden区占用恰好是第四个对象的大小。其它占用则为程序执行所需的一些对象，可以忽略。

结论：

• intellij idea执行代码，插入了自己的逻辑，导致gc日志不符合预期。
• gc日志中的快照并不是gc后第一个对象分配之后的快照，比如第一次打印的日志，eden区包含了不止一个对象。