前几天在做功能压测时发现应用在启动时出现了4次Full GC,并且当时还没有开始压测,当时排查了很长时间,最终发现是犯了一个低级错误,本想配置-Xss256k的,结果把-XX:MetaspaceSize配置成了256k。o(╥﹏╥)o

本着不在同一块儿石头上绊倒两次的原则,又系统了学习了一下Full GC的触发条件和如何查看GC日志。

简单来说有如下几种情况会触发gc

1.调用System.gc()触发Full GC

package gc;

import java.util.ArrayList;
import java.util.List;

/**
 * JKD版本:jdk1.8.0_111
 * JVM参数:-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xms2g -Xmx2g -Xmn1g
 *
 * @author Bo.Zhao
 * @since 19/4/21
 */
public class SysGc {
    public static void main(String[] args) {
        for (int i = 0; i < 5; i++) {
            createBigObject(21);
            System.gc();
        }
    }

    private static void createBigObject(int n) {
        List<byte[]> bytesList = new ArrayList<>();
        for (int i = 0; i < n; i++) {
            bytesList.add(new byte[1024 * 1024 * 10]);
        }
        if (bytesList.size() < 20) {
            throw new RuntimeException("this is test");
        }
    }
}

本次触发GC日志片段如下:

0.585: [GC (System.gc()) [PSYoungGen: 251986K->1403K(917504K)] 251986K->1411K(1966080K), 0.0020937 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.587: [Full GC (System.gc()) [PSYoungGen: 1403K->0K(917504K)] [ParOldGen: 8K->1261K(1048576K)] 1411K->1261K(1966080K), [Metaspace: 3508K->3508K(1056768K)], 0.0083870 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

我们可以发现,0.587秒因为调用System.gc()的原因发生了一次Full GC。其中其中新生代的使用内存从1403K变为0k,新生代内存总量为917504K;老年代内存使用量从8k上涨到1261K,老年代内存总量是1048576K;堆内存使用1411k减少到1261k,堆内存总量是1966080K;元空间内存使用情况无变动3508K->3508K,元空间总量是1056768K。本次GC总CPU耗时0.01秒,持续0.01秒。

2.堆空间内存不足时,触发Full GC

/**
 * JDK版本:jdk1.8.0_111
 * JVM参数:-Xms200m -Xmx200m -Xmn32m -XX:+UseParallelGC -XX:+UseParallelOldGC
 *
 * @author Bo.Zhao
 * @since 19/4/21
 */
public class AllocationFailure {
    public static void main(String[] args) {
        // 设置大对象,新生代内存有32m,不够
        byte[] bigObj1 = new byte[1024 * 1024 * 160];
        byte[] bigObj2 = new byte[1024 * 1024 * 70];
    }
}

GC日志片段

0.514: [GC (Allocation Failure) [PSYoungGen: 4445K->1386K(28672K)] 168285K->165234K(200704K), 0.0036830 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.518: [Full GC (Ergonomics) [PSYoungGen: 1386K->0K(28672K)] [ParOldGen: 163848K->165101K(172032K)] 165234K->165101K(200704K), [Metaspace: 3509K->3509K(1056768K)], 0.0103061 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
0.528: [GC (Allocation Failure) [PSYoungGen: 0K->0K(28672K)] 165101K->165101K(200704K), 0.0019968 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.530: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(28672K)] [ParOldGen: 165101K->165082K(172032K)] 165101K->165082K(200704K), [Metaspace: 3509K->3509K(1056768K)], 0.0108352 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

通过GC日志我们可以发现,0.530秒(创建第一个大对象之后创建第二个大对象之前)因为内存分配(Allocation Failure)失败导致了一次Full GC,在这里Full GC之前先执行了一次Minor GC。Minor GC执行是没有回收掉新生代中的对象,堆内存使用没有变化;Full GC之后,新生代内存没有变化,老年代内存使用从165101K降低到165082K(几乎没有变化)。这个程序最后内存溢出了,因为没有可用的堆内存创建70m的大对象。

注意:0.518秒那次Full GC也是在创建第一个大对象之后创建第二个大对象之前,这次触发Full GC应该是因为在创建新对象时触发内存担保机制导致的。

3.永久代或元空间内存不足时触发Full GC

注意:永久代是Java7里面的概念,在Java8中已经没有永久代,改为元空间。但两者也有一些不同,在此不做讨论。

package gc;

/**
 * JKD版本:jdk1.8.0_111
 * JVM参数:-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:MetaspaceSize=256k
 *
 * @author Bo.Zhao
 * @since 19/4/21
 */
public class MetadataGc {
    public static void main(String[] args) {
        System.out.println("hello world");
    }
}

GC日志片段如下

0.288: [GC (Metadata GC Threshold) [PSYoungGen: 3347K->1328K(38400K)] 3347K->1328K(125952K), 0.0015915 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.290: [Full GC (Metadata GC Threshold) [PSYoungGen: 1328K->0K(38400K)] [ParOldGen: 0K->1176K(61952K)] 1328K->1176K(100352K), [Metaspace: 2946K->2946K(1056768K)], 0.0065967 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

我们可以看到,第0.290秒因为突破了元空间的初始限制(256k)导致触发了一次Full GC,注意看[Metaspace: 2946K->2946K(1056768K)],这里元空间的使用内存量已经突破了初始值256k,同时本次垃圾回收没有在元空间释放掉内存。所以推测应该是元空间内存使用量超出初始值时就会触发Full GC。因此为了避免应用启动时出现元空间内存回收,最好是把元空间初始大小稍微调高一些,具体值需要看应用需要加载的类的数量等。

4.内存担保机制触发的Full GC

内存担保机制指在JVM在内存分配的时候,新生代内存不足时,把新生代的存活的对象搬到老生代,然后新生代腾出来的空间用于为分配给最新的对象。这里老生代是担保人。

package gc;

/**
 * JDK版本:jdk1.8.0_111
 * JVM参数:-XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xms200m -Xmx200m -Xmn30m -XX:+UseParallelGC -XX:+UseParallelOldGC
 *
 * @author Bo.Zhao
 * @since 19/4/21
 */
public class ErgonomicsGc {
    public static void main(String[] args) {
        // 大对象直接放入老年代
        byte[] bigObj1 = new byte[1024 * 1024 * 160];
        // 下次创建新对象时,发现新生代内存不足;
        // 但是如果把新生代现有的对象挪到老年代之后,新生代即可容纳新对象。因此触发内存担保。
        byte[] bigObj2 = new byte[1024 * 1024 * 20];
    }
}

GC日志如下:

0.493: [GC (Allocation Failure) [PSYoungGen: 4786K->1386K(27136K)] 168626K->165234K(201216K), 0.0022455 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
0.495: [Full GC (Ergonomics) [PSYoungGen: 1386K->0K(27136K)] [ParOldGen: 163848K->165100K(174080K)] 165234K->165100K(201216K), [Metaspace: 3506K->3506K(1056768K)], 0.0134643 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

PSYoungGen      total 27136K, used 20715K [0x00000000fe200000, 0x0000000100000000, 0x0000000100000000)
  eden space 23552K, 87% used [0x00000000fe200000,0x00000000ff63af98,0x00000000ff900000)
  from space 3584K, 0% used [0x00000000ff900000,0x00000000ff900000,0x00000000ffc80000)
  to   space 3584K, 0% used [0x00000000ffc80000,0x00000000ffc80000,0x0000000100000000)
 ParOldGen       total 174080K, used 165100K [0x00000000f3800000, 0x00000000fe200000, 0x00000000fe200000)
  object space 174080K, 94% used [0x00000000f3800000,0x00000000fd93b268,0x00000000fe200000)
 Metaspace       used 3515K, capacity 4498K, committed 4864K, reserved 1056768K
  class space    used 387K, capacity 390K, committed 512K, reserved 1048576K

我们设置了新生代的内存是30m(实际是26.5m),默认Eden:Survivor0:Survivor1是8:1:1。此时新生代Eden区总内存大小为24m(实际是23m)。

GC日志中显示,在0.495秒分配第二个对象时,发现新生代内存不足创建新对象。通过计算发现如果把新生代的现有对象挪到老年代,那么新生代就可以放下第二个分配的对象。因此触发内存担保机制,新生代原对象通过Full GC进入老年代,第二个在新生代创建成功。在GC日志最后,我们可以看到新生代、老年代、元空间的内存使用情况。

最后,本次显式设置的JVM参数含义如下:

-XmsN 设置堆的初始内存大小为N
-XmxN 设置堆的最大内存大小为N
-XmnN 设置新生代的内存大小为N
-XX:MetaspaceSize=N 设置元空间初始配置为N
-XX:+PrintGC 打印GC情况
-XX:+PrintGCTimeStamps 在发生GC时打印发生时间
-XX:+PrintGCDetails 在发生GC时打印GC日志
-XX:+UseParallelGC 新生代使用并行垃圾回收算法
-XX:+UseParallelOldGC 老年代使用并行垃圾回收算法