FullGC触发条件和解读GC日志

最新推荐文章于 2024-09-18 10:49:43 发布

_解牛_

最新推荐文章于 2024-09-18 10:49:43 发布

阅读量1w

点赞数 2

分类专栏： JVM 文章标签： JVM Full GC GC日志

本文链接：https://blog.csdn.net/yuxxz/article/details/89432786

版权

JVM 专栏收录该内容

1 篇文章 0 订阅

订阅专栏

前几天在做功能压测时发现应用在启动时出现了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 老年代使用并行垃圾回收算法