gc日志分析

轻GC

先来这么一个小程序：

public class TestGCMessage {

    public static void main(String[] args) {
        int size = 1024 * 1024;
        byte[] b1 = new byte[2 * size];
        byte[] b2 = new byte[2 * size];
        byte[] b3 = new byte[3 * size];
    }
}

然后配上启动参数：

-verbose:gc
-Xmx20m
-Xms20m
-Xmn10m
-XX:+PrintGCDetails
-XX:SurvivorRatio=8

这里我们要求打印详细的gc日志。

并且堆空间的起始大小和最大大小都是20m，防止gc后的内存抖动。

然后新生代是10m。

所以老年代也是10m。

最后伊甸园和存活区的比例是8:1，两个存活区是一样大的，所以伊甸园是8m，两个存活区都是1m。

我们的程序要在伊甸园分配三个对象，总大小是7m。但是由于jvm自己也要初始化对象，所以还是发生了轻GC。

[GC (Allocation Failure) [PSYoungGen: 6122K->904K(9216K)] 6122K->5008K(19456K), 0.0025888 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 4142K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 39% used [0x00000000ff600000,0x00000000ff929ab8,0x00000000ffe00000)
  from space 1024K, 88% used [0x00000000ffe00000,0x00000000ffee2020,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 10240K, used 4104K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  object space 10240K, 40% used [0x00000000fec00000,0x00000000ff002020,0x00000000ff600000)
 Metaspace       used 3249K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 353K, capacity 388K, committed 512K, reserved 1048576K

轻GC的触发时机是Allocation Failure。分配对象失败。

年轻代用的垃圾收集器是PSYoungGen，它用的是copy的算法，也就是把所有的垃圾都挪到空闲的内存区域。好处是很简单，坏处是总要有一块内存区域是空闲的。

我们这里就一定会有一块survivor区是空闲的，换句话说，有1m是必定要浪费的。

PSYoungGen: 6122K->904K(9216K)

表示年轻代的回收情况。

总的是$9216/1024=9$。这和我们预测的是一样的，年轻代一定是有1m是浪费的。

然后$6122-904=5218$。

伊甸园释放了5218k的对象。

6122K->5008K(19456K)

是整个堆的情况。

堆大小为$19456/1024=19$。一样的道理，1m是废掉的。

然后$6122-5008=1114$。

总的堆空间释放了1114k的空间。为什么伊甸园会释放的比总的堆空间的还要多呢？

这里$5218-1114=4014$。而日志显示：

 ParOldGen       total 10240K, used 4104K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)

老年代正好有4014k的大小。

所以伊甸园释放的5218中有4014是挪到了老年代，真正被回收的是1114k。

Full GC

如果程序变成这样：

  public static void main(String[] args) {
        int size = 1024 * 1024;
        byte[] b1 = new byte[2 * size];
        byte[] b2 = new byte[2 * size];
        byte[] b3 = new byte[2 * size];
        byte[] b4 = new byte[3 * size];
    }

此时的gc日志为：

[GC (Allocation Failure) [PSYoungGen: 8170K->888K(9216K)] 8170K->7040K(19456K), 0.0029220 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Ergonomics) [PSYoungGen: 888K->0K(9216K)] [ParOldGen: 6152K->6759K(10240K)] 7040K->6759K(19456K), [Metaspace: 3295K->3295K(1056768K)], 0.0047704 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 9216K, used 3238K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 39% used [0x00000000ff600000,0x00000000ff929858,0x00000000ffe00000)
  from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 10240K, used 6759K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  object space 10240K, 66% used [0x00000000fec00000,0x00000000ff299da8,0x00000000ff600000)
 Metaspace       used 3303K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 359K, capacity 388K, committed 512K, reserved 1048576K

此时经历了两次gc。

第一次：新生代清理了$8170-888=7282$。

整个堆清理了$8170-7040=1130$。

此时新生代还剩下888k。老年代还剩下$7282-1130=6152$。

第二次：这是一次Full GC。全部干一遍。新生代直接清空。老年代用的是ParOldGen垃圾收集器，算法是标记-整理-清除。老年代的空间涨了:6152K->6759K。因为有垃圾晋升到了老年代。最后整个堆剩下的就是6759K。