JVM系列-读懂 GC 日志

时间  2020-07-26
标签 jvm 系列 读懂 日志 栏目 Java 繁體版
原文   原文链接

Java 生态发展到今天，JVM （Java Virtual Machine）的价值可能已经超过了 Java 语言自己。java

而 GC （垃圾回收）机制也是 JVM 的核心之一，在程序运行的过程当中，GC 的过程会以日志的形式记录下来，看懂 GC 日志是研究 GC 机制的基础，GC日志也是判断 Java 程序运行是否正常的重要依据。bash

这篇文章将会从多个方面来详细说明 GC 日志，本文基于 OpenJDK1.8 和 HotSpot 虚拟机。app

在开始说明 GC 机制以前，须要先了解一下相关的内容。工具

$ java -version
openjdk version "1.8.0_40"
OpenJDK Runtime Environment (build 1.8.0_40-b25)
OpenJDK 64-Bit Server VM (build 25.40-b25, mixed mode)
复制代码

上面是使用 java -version 打印出来的信息，里面信息量很大，好比上面代表这个 JDK 是 openjdk1.8，当前 JVM 是 Server VM，使用的是混合执行模式。ui

JVM 分为 Client VM 和 Server VM，Client VM 适用内存小，适合一些交互性强的场景，好比桌面应用，Server 则适用于内存大的服务端环境。spa

可使用下面的命令进行 JVM 的切换。操作系统

$ java -client -version
$ java -server -version
复制代码

可是须要注意，对于 64 位的 JDK，只有 Server VM， Java 已经放弃桌面应用，之后重点关注 Server VM 就能够。3d

Java 是一门复杂的语言，既能解释执行，也能编译执行，也能够两种方式共存，默认就是两种方式并存 (mixed mode)，由 JVM 来决定把哪些代码编译执行。日志

这三种执行方式也能够进行切换：code

$ java -Xint -version # 彻底解释执行
$ java -Xcomp -version # 彻底编译执行
$ java -Xmixed -version # 混合执行
复制代码

Client VM 和 Server VM 的 GC 机制不同，这篇文章中，咱们只关注 Server VM 的 GC。

JVM 内存模型

下面这两张图很重要，只要提到 JVM，就会用到下面两张图（HotSpot 虚拟机）。

JVM 内存模型以下：


在 Java 8 之后，使用元空间来实现方法区，而且不占用堆内的空间，而是使用本地内存来实现。

堆内部的各个区域分布以下：


其中 Eden、from 和 to 区域称为新生代（Young）区域，这三个区域大小的比例默认为 8:1:1，整个新生代区域和老年代区域的比例为 1:2。

GC 基本分类

GC 整体上能够分红两类，对部分区域的 GC 和整堆的 GC（Full GC），通常状况下，只会发生部分区域的 GC，若是常常发生整堆的 GC，可能存在内存泄漏等状况。

对部分区域的 GC 有可能发生在新生代（Minor GC），也有可能发生老年代（Major GC）。

也有一种特殊的状况，若是使用的是 G1 收集器，那么会同时对新生代和老年代进行 GC。


当咱们在说到 JVM 的 GC 时，通常都指对 JVM 堆的回收，大多数状况下，只有堆内的内存才会被回收。

GC 参数

默认状况下，Java 程序在运行时并不会打印 GC 日志，须要加上下面的 JVM 参数：

-verbose:gc # 控制台打印 gc 日志
-XX:+PrintGCDetails # 打印 gc 过程的细节
-XX:+PrintGCDateStamps # 打印 gc 的发生的时间戳
复制代码

若是想保存为文件，则须要加上下面的参数，须要注意的是，若是保存为文件，则控制台就再也不打印 gc 日志：

-Xloggc:gc.log # 将 gc 日志保存成文件，默认在项目的根目录，能够根据项目的状况进行调整
复制代码

还有一些其余辅助性的参数:

-XX:+PrintGCApplicationStoppedTime # 打印 stop world 的时间
-XX:+PrintGCApplicationConcurrentTime # 打印程序未中断运行的时间
-XX:+PrintHeapAtGC # 打印 GC 先后的堆栈信息
-XX:+PrintTenuringDistribution # 打印每次 minor GC 后新的存活周期的阈值
复制代码

认识 GC 日志

首先来了看一段基本的日志，设置的参数为：

-Xms8m
-Xmx8m
-verbose:gc
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
复制代码

而后执行下面的代码：

public class NoGC {
    public static void main(String[] args) {
        System.out.println("No gc");
    }
}
复制代码

产生的日志以下：

Heap
 PSYoungGen      total 2048K, used 1400K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 91% used [0x00000000ffd80000,0x00000000ffede3d0,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
 Metaspace       used 3018K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 323K, capacity 388K, committed 512K, reserved 1048576K
复制代码

运行上面的代码以后，就会产生上面的日志，上面的日志显示在运行这段代码的时候尚未进行 GC，只是把堆的内存状态打印出来了。

上面的 Heap 表示这是 JVM 的堆，主要分红三个部分，PSYoungGen（新生代），ParOldGen（老年代） 和 Metaspace（元数据空间，也就是方法区）。

须要注意的是，元空间不从堆里面分配内存，而是使用堆外内存，也就是直接从运行的机器上分配内存。但结构上与堆在一块儿，元空间还有一个名称是非堆。

PSYoungGen 表示的是新生代，而且使用 Parallel Scavenge 收集器来 GC，ParOldGen 表示老年代，而且使用 Parallel old 收集器来 GC，Server VM 使用的就是这对收集器的组合。

新生代分红 eden、from 和 to 三个区域，from 和 to 区域也称之为 Survivor 区域，在上面的日志中，咱们能够看出每一个区域所占的大小以及使用状况。

老年代没有再细分为其余的区域，那些在新生代没有被淘汰的的对象会进入老年代。

发生部分 GC

执行下面这段代码：

public class NormalGC {
    public static void main(String[] args) throws InterruptedException {

        Object o  = new Object();
        for (int i = 0; ;i++) {
            Thread.sleep(1000);
            byte[] b = new byte[1024 * 1024];
            b = null;
        }
    }
}
复制代码

产生的 GC 日志以下：

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 2048K, used 1536K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 100% used [0x00000000ffd80000,0x00000000fff00000,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
 Metaspace       used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 333K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 2048K, used 496K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
  eden space 1536K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x00000000fff00000)
  from space 512K, 96% used [0x00000000fff00000,0x00000000fff7c010,0x00000000fff80000)
  to   space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
 ParOldGen       total 5632K, used 64K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
  object space 5632K, 1% used [0x00000000ff800000,0x00000000ff810000,0x00000000ffd80000)
 Metaspace       used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 333K, capacity 388K, committed 512K, reserved 1048576K
}
Total time for which application threads were stopped: 0.0029243 seconds, Stopping threads took: 0.0000297 seconds
Application time: 1.0001808 seconds
复制代码

先总体来看一下这个日志的结构。

最前面一部分是进行 GC 以前堆内存的分配状况，invocations 表示垃圾回收的次数，括号里面是发生 Full GC 的次数。

而后就是 GC 回收的细节，下面详细说，再而后是 GC 以后堆的内存分配状况，与 GC 的以前堆的状况能够有个对比。

倒数第二行是 PrintGCApplicationStoppedTime 参数打印出来的信息，表示由于 GC 而产生的停顿时间。最后一行是 PrintGCApplicationConcurrentTime 参数所打印出来的信息，表示程序运行的时间。

下面来看 GC 的回收细节，经过上面的日志能够看到新生代的 eden 区已经满了，而后就出现了下面这条日志:

[GC (Allocation Failure) 
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs] 
[Times: user=0.01 sys=0.00, real=0.01 secs] 
复制代码

这条日志就是在新生代进行了 minor GC。

第一行表示发起此次 GC 的缘由是分配新的内存失败（Allocation Failure），第二行是由于咱们加上了 -XX:+PrintTenuringDistribution 这个参数，它会打印出新生代对象的年龄，以及对象进入老年代的年龄阈值，这里默认是 7，最大是 15 ，能够经过参数进行调整。

第三行就是具体的回收信息，PSYoungGen 表示这是发生在新生代的回收，分开来看各部分：

  • 1536K->496K(2048K) 表示：回收前该区域已使用的空间→回收后该区域使用的空间(该区域总空间)，这里是指新生代区域
  • 1536K->560K(7680K) 表示：回收前堆中已使用的空间→回收后堆中已使用的空间(堆的总空间)
  • 0.0024873 secs：表示 GC 进行的时间，单位为秒
  • Times: user=0.01 sys=0.00, real=0.01 secs： 这部分也是对 GC 时间进行统计，可是是从操做系统的角度来统计，分被表示用户态时间，内核态时间和时钟时间

发生 Full GC

执行下面的代码就会发生 Full GC：

public class FullGC {
    public static void main(String[] args) {
        int size = 1024 * 1024;
        byte[] b = new byte[size];

        b = null;

        System.gc();
    }
}
复制代码

Full GC 其余的部分与上面部分 GC 基本一致，下面重点来看发生 Full GC 时，各个区域的回收状况：

[Full GC (System.gc()) 
[PSYoungGen: 480K->0K(2048K)] 
[ParOldGen: 1104K->473K(5632K)] 
1584K->473K(7680K),
[Metaspace: 3107K->3107K(1056768K)], 
0.0055681 secs] 
[Times: user=0.02 sys=0.00, real=0.01 secs] 
复制代码

第一行是表示此次发生的是 Full GC，发起的缘由是调用了 System.gc()。

第二行和第三行分别表示对新生代和老年代的回收，回收前后各个区域占用的内存状况都会打印出来。

第四行一样表示整个堆内存的回收状况。

第五行表示对元空间也进行了垃圾回收，虽然什么也没有回收成功。

若是内存泄露或溢出

OutOfMemoryError 是一种常见的错误，通常在抛出这个异常以前，都会出现一次 Full GC。

public class Leak2GC {
    public static void main(String[] args) {
         Vector strings = new Vector();

        for (int i = 0;  ;i++) {
            String str = new String("Hello gc" + i);
            strings.add(str);
            str = null;
        }
    }
}
复制代码

执行上面的代码以后，就会出现下来的日志：

[Full GC (Allocation Failure) 
[PSYoungGen: 943K->943K(2048K)] 
[ParOldGen: 5556K->5539K(5632K)] 
6499K->6483K(7680K), 
[Metaspace: 3135K->3135K(1056768K)],
0.0260635 secs]
[Times: user=0.14 sys=0.00, real=0.03 secs] 
复制代码

即便进行了 Full GC，也没法对各个区域进行有效的回收，在没法回收空间以后，就会报出下面的错误：

Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOf(Arrays.java:3210)
	at java.util.Arrays.copyOf(Arrays.java:3181)
	at java.util.Vector.grow(Vector.java:266)
	at java.util.Vector.ensureCapacityHelper(Vector.java:246)
	at java.util.Vector.add(Vector.java:782)
	at cn.rayjun.java.java8.gc.Leak2GC.main(Leak2GC.java:12)
复制代码

GC 信息统计分析

经过上面的内容，应该就能够看懂 GC 的日志信息了，在不少状况下，咱们经过部分的日志没法判断问题。

因此就有必要对总体的 GC 状况进行统计，通常会借助其余的统计工具来进行。

最直接的方式就是使用 JDK 的内置工具，jstat ，具体使用以下，参数为 pid。

$ jstat -gc 24991
S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
512.0  512.0   0.0    0.0    1536.0   1024.0    5632.0     4755.0   4864.0 3477.4 512.0  378.3      54    0.082   1      0.018    0.099
复制代码

各个数据项的含义以下：

  • S0C：from 区的大小
  • S1C：to 区的大小
  • S1U：from 区使用的大小
  • S1U：to 去使用的大小
  • EC：eden 区的大小
  • EU：eden 去使用的大小
  • OC：老年代的大小
  • OU：老年代使用的大小
  • MC：方法区的大小
  • MU：方法区使用的大小
  • CCSC：压缩类空间大小
  • CCUS：压缩类空间使用的大小
  • YGC：年轻代垃圾回收的次数
  • YGCT：年轻代垃圾回收消耗时间
  • FGC：老年代垃圾回收的次数
  • FGCT：老年代垃圾回收消耗时间
  • GCT：垃圾回收的总时间

也可使用可视化的分析工具来对 CG 日志进行分析，好比 gceasy.io/。

若是使用其余的收集器

在上面的日志中，GC 使用的是默认收集器组合，咱们也可使用其余的收集器来，好比使用 UseConcMarkSweepGC 参数来启用 CMS收集器。

使用了这个收集器以后，日志以下：

[GC (Allocation Failure) [ParNew: 1384K->256K(2432K), 0.0022504 secs] 1384K->491K(7936K), 0.0022693 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (System.gc()) [CMS: 235K->472K(5504K), 0.0016647 secs] 1582K->472K(7936K), [Metaspace: 3009K->3009K(1056768K)], 0.0016851 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
复制代码

稍微有了一点变化，新生代的收集器使用了 ParNew 收集器，老年代使用了 CMS收集器，日志其余部分的含义没有变化。

也能够根据本身的需求去使用其余的收集器。

文 / Rayjun

                                                      
相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程