JVM之GC日志-技术圈

出自抽象写实派大作家本人之手：happy 2nd anniversary ~

happy？ happy个狗~

❝
JVM 相关的理论知识网上已经被讲的比较详细了，但是，不管是日常工作或是面试考察，越来越多的开始关注相关的实战经验。所以，小弟希望可以从之前的工作经历和前人的总结中，讲述一些 jvm 实际操作相关的知识，包括但不限于 GC 日志解析、GC 时间异常相关实例和发生原因、OOM 等 jvm 相关异常等等~不定时更新吧~ 大家一起交流。❞

让程序按期望GC

为了方便我们查看 GC 日志，我们来写个方便 GC 发生的程序，参见《深入理解 java 虚拟机》

private static final int _1MB = 1024 * 1024;

  public static void main(String[] args) {

    MyObject ob1, ob2, ob3, ob4,ob5;

    ob1 = new MyObject("ob1",2 * _1MB);
    ob2 = new MyObject("ob2",2 * _1MB);
    ob3 = new MyObject("ob3",2 * _1MB);
    ob4 = new MyObject("ob4",2 * _1MB);
  }

  privatestaticclass MyObject{
    private String name;
    privatebyte[] space;
    public MyObject(String name, int size) {
      this.name = name;
      this.space = newbyte[size];
      System.out.println(name + " init ~");
    }
  }

我们这里除了真正的内存占用的 space，还加上了 name 来标示对象顺序，虽然内存占用会不太准确，但应该是不影响我们对 gc 的理解的。

而运行时的 vm operation 我们设置为：

-Xms20M
-Xmx20M
-XX:NewSize=10M
-XX:+PrintGCDetails
-XX:SurvivorRatio=8

从理论上分析，因为我们 young 区设置了 10M，而 eden 区和 S 区的占比为 8:1，因此 eden 区应该是 8M, 两个 S 区分别都是 1M。

当我们连续创建了三个 2M 的对象之后，在创建第四个对象时，发现，eden 区放不下了，因此触发一次 young gc,实际运行后的 GC 日志如下：

ob1 init ~
ob2 init ~
ob3 init ~
[GC (Allocation Failure) [PSYoungGen: 8046K->594K(9216K)] 8046K->6746K(19456K), 0.0030729 secs][times: user=0.01 sys=0.01, real=0.00 secs]
[Full GC (Ergonomics) [PSYoungGen: 594K->0K(9216K)] [ParOldGen: 6152K->6642K(10240K)] 6746K->6642K(19456K), [Metaspace: 3088K->3088K(1056768K)], 0.0080044 secs][times: user=0.00 sys=0.00, real=0.01 secs]
ob4 init ~
Heap
PSYoungGen total 9216K, used 2289K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 8192K, 27% used [0x00000007bf600000,0x00000007bf83c460,0x00000007bfe00000)
from space 1024K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bff00000)
to space 1024K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007c0000000)
ParOldGen total 10240K, used 6642K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
object space 10240K, 64% used [0x00000007bec00000,0x00000007bf27cad8,0x00000007bf600000)
Metaspace used 3095K, capacity 4500K, committed 4864K, reserved 1056768K
class space used 339K, capacity 388K, committed 512K, reserved 1048576K

我们可以看到，在 ob3 init 之后，确实进行了 GC，不过是一次 ygc，一次 fgc ,姑且不管 fgc 发生的原因，我们先来解析一下 GC 日志

young gc 日志解析

[GC (Allocation Failure) [PSYoungGen: 8046K->594K(9216K)] 8046K->6746K(19456K), 0.0030729 secs][times: user=0.01 sys=0.01, real=0.00 secs]

[GC(Allocation Failure)

GC类型(GC原因) ，Allocation Failure基本都是空间不够，是正常的

[PSYoungGen: 8046K->594K(9216K)]

GC策略:gc前内存占用->gc后内存占用（新生代总大小）

8046K->6746K(19456K)

gc前->gc后jvm堆内存占用（jvm堆大小）

0.0030729 secs

GC耗时

[times: user=0.01 sys=0.01, real=0.00 secs]

[用户耗时，系统耗时，实际耗时]

full gc 日志解析

full gc 和 young gc 的日志基本上差不多的

[Full GC (Ergonomics) [PSYoungGen: 594K->0K(9216K)]         [ParOldGen: 6152K->6642K(10240K)] 6746K->6642K(19456K), [Metaspace: 3088K->3088K(1056768K)], 0.0080044 secs][times: user=0.00 sys=0.00, real=0.01 secs]
[gc类型   (gc原因)      [ygc策略]:young区gc前后变化(young总大小)] [fgc策略：old区gc前后(old区总大小)] jvm堆gc前后变化(堆总大小),[元数据区信息],                    fgc耗时         [gc耗时详细信息]