两个奇怪的GC日志解析

前段时间有空学习了下GC内存的分配和回收，期间遇到两次非常奇怪的GC日志，这里记录入下。

//-Xms10M -Xmx10M  -Xmn3M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+PrintCommandLineFlags
启动的参数 分配最大10M的堆 年轻代3M
程序运行每次也分需要3M的内存
        final int oneMB = 1* 1024 * 1024;
        int count = 0;
        while(true) {
            for (int i = 1; i < 100; i++) {
                byte[] b = new byte[oneMB * 3];
                System.out.println(" --- " + i);
                Thread.sleep(1000*1);

            }
        }

--- 1
--- 2
[GC (Allocation Failure) [PSYoungGen: 731K->432K(2560K)] 6875K->6584K(9728K), 0.0018651 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 432K->400K(2560K)] 6584K->6552K(9728K), 0.0021875 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (Allocation Failure) [PSYoungGen: 400K->0K(2560K)] [ParOldGen: 6152K->338K(7168K)] 6552K->338K(9728K), [Metaspace: 2649K->2649K(1056768K)], 0.0065318 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
--- 3
--- 4
[GC (Allocation Failure) [PSYoungGen: 40K->0K(2560K)] 6523K->6482K(9728K), 0.0013011 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] 6482K->6482K(9728K), 0.0011310 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[Full GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] [ParOldGen: 6482K->327K(7168K)] 6482K->327K(9728K), [Metaspace: 2649K->2649K(1056768K)], 0.0052355 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
--- 5

--1 就是一次分配内存
可以看到第三次的分配内存的时候产生了2次YongGC，当时我非常奇怪还以为遇到了BUG。 现在想起来应该是参数设置的问题。 年轻代的内存和程序所需要分配的内存大小相当。前面两次直接因为年代不足从老年代分配了。第三次的时候老年代已经不能满足，所以先执行一次YGC 回收一下，发现还是不足，但是可能经过某种运算（这只是猜测）认为年轻代再回收一次还是能满足。 所以有回收了一次。 发现还是不能满足最后进行了一次FULL GC。
正常情况下 生产上应该不会出现这种问题 因为生产上年轻代的内存肯定是远远大于程序需要分配的内存，不过连续两次YGC还是不是特别清楚，到底是因为一种补偿机制还是因为算法原因。

第二个比较神奇的日志是
这次我们正常设置启动参数

-Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+PrintCommandLineFlags
堆的大小为20M 年轻代10M

    
       final int oneMB = 1* 1024 * 1024;
        List<byte[]> l = new ArrayList<>(6); //这次为例测老年年回收 用一个list来装备引用对象
        int count = 0;
        while(true) {
            for (int i = 1; i < 100; i++) {
                byte[] b = new byte[oneMB * 1]; //每次分配1M
                System.out.println(" --- " + i);
                l.add(b);
                if (l.size() > 5) { //快满的时候释放掉内存
                    l.clear();
                    System.out.println(" --- " + i + "clear");
                }
                Thread.sleep(1000*1);
            }
        }

大概运行20多秒后
--- 20
--- 21
[GC (Allocation Failure) [PSYoungGen: 7940K->368K(9216K)] 11020K->6520K(19456K), 0.0046196 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
--- 22
--- 23
--- 24
--- 24clear
--- 25
--- 26
--- 27
--- 28
[GC (Allocation Failure) --[PSYoungGen: 7695K->7695K(9216K)] 13847K->16919K(19456K), 0.0050605 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[Full GC (Ergonomics) [PSYoungGen: 7695K->0K(9216K)] [ParOldGen: 9224K->4411K(10240K)] 16919K->4411K(19456K), [Metaspace: 2650K->2650K(1056768K)], 0.0081017 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
--- 29

我们知道正常情况下YGC多是 7940K->368K(9216K) 这种变少的。
出现这种13847K->16919K(19456K), 不是很诡异吗。
当时堆内存状态为（500ms打印一次）

jstat -gcutil 38508 500 100
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 39.06 76.94 60.16 54.48 56.16 3 0.007 0 0.000 0.007
0.00 39.06 89.45 60.16 54.48 56.16 3 0.007 0 0.000 0.007
0.00 39.06 89.45 60.16 54.48 56.16 3 0.007 0 0.000 0.007
0.00 0.00 14.45 43.08 54.49 56.16 4 0.011 1 0.004 0.015
0.00 0.00 14.45 43.08 54.49 56.16 4 0.011 1 0.004 0.015

可以看到当时S1区有39.06的内容。 这次YGC正在将S1的内容拷贝到OLD区 但是因为当时内存碎片或者其他原因 达到old区可以用的内存占比？，导致old区的内存也不太够了 这次促发了一次fullGC然后回收了年轻代的内存。 所以出现了这条诡异的日志吧。