JVM 分析GC日志

GC日志参数

-verbose:gc

输出gc日志信息，默认输出到标准输出

-XX:+PrintGC

输出GC日志。类似：-verbose:gc

-XX:+PrintGCDetails

在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况

-XX:+PrintGCTimeStamps

输出GC发生时的时间戳

-XX:+PrintGCDateStamps

输出GC发生时的时间戳（以日期的形式，如2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC

每一次GC前和GC后，都打印堆信息

-Xloggc:<file>

表示把GC日志写入到一个文件中去，而不是打印到标准输出中

GC日志格式

GC日志分类

MinorGC

MinorGC(或young GC或YGC)日志：

[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

FullGC

Full GC日志介绍：

[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

GC日志结构剖析

垃圾收集器

使用Serial收集器在新生代的名字是Default New Generation，因此显示的是"[DefNew"
使用ParNew收集器在新生代的名字会变成"[ParNew",意思是"Parallel New Generation"
使用Parallel Scavenge收集器在新生代的名字是"[PSYoungGen",这里的JDK1.7使用的就是PSYoungGen
使用Parallel Old Generation收集器在老年代的名字是"[ParOldGen"
使用G1收集器的话，会显示为"garbage-first heap"

Allocation Failure：表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。

GC前后情况

我们可以发现GC日志格式的规律一般都是：GC前内存占用—>GC后内存占用（该区域内存总大小）

[PSYoungGen: 5986K->696K(8704K)] 5986K->704K(9216K)

中括号内：GC回收前年轻代堆大小，回收后大小，（年轻代堆总大小）

括号外：GC回收前年轻代和老年代大小，回收后大小，（年轻代和老年代总大小）

GC时间

GC日志中有三个时间：user，sys和real

user – 进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
sys – 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间。
real – 程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行gc，这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。

由于多核的原因，一般的GC事件中，real time是小于sys + user time的，因为一般是多个线程并发的去做GC，所以real time是要小于sys+user time的。如果real>sys+user的话，则你的应用可能存在下列问题：IO负载非常重或者是CPU不够用。

Minor GC日志解析

2020-11-20T17:19:43.265-0800: 0.822: [GC (ALLOCATION FAILURE) [PSYOUNGGEN: 76800K->8433K(89600K)] 76800K->8449K(294400K), 0.0088371 SECS] [TIMES: USER=0.02 SYS=0.01, REAL=0.01 SECS]

2020-11-20T17:19:43.265-0800

日志打印时间日期格式如2013-05-04T21:53:59.234+0800

0.822

gc发生时，Java虚拟机启动以来经过的秒数

[GC (ALLOCATION FAILURE)

发生了一次垃圾回收，这是一次Minor GC。它不区分新生代GC还是老年代GC，括号里的内容是gc发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能够存放需要分配的数层而失败。

[PSYOUNGGEN: 76800K->8433K(89600K)]

PSYoungGen:表示GC发生的区域，区域名称与使用的GC收集器是密切相关的

Serial收集器：Default New Generation显示DefNew
ParNew收集器：ParNew
Parallel Scanvengel收集器：PSYoung
老年代和新生代同理，也是和收集器名称相关

76800K->8433K(89600K：GC前该内存区域已使用容量·>GC后该区域容量（该区域总容量）

如果是新生代，总容量则会显示整个新生代内存的9/10，即eden+from/to区
如果是老年代，总容量则是全部内存大小，无变化

76800K->8449K(294400K)

在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量·>GC堆内存容量（堆内存总容量）

堆内存总容量=9/10新生代+老年代<初始化的内存大小

0.0088371 SECS

整个GC所花费的时间，单位是秒

[TIMES: USER=0.02 SYS=0.01, REAL=0.01 SECS]

user：指的是CPU工作在用户态所花费的时间

sys：指的是CPU工作在内核态所花费的时间

rea：指的是在此次Gc事件中所花费的总时间

Full GC日志解析

2020-11-20T17:19:43.794-0800: 1.351: [FULL GC (METADATA GC THRESHOLD) [PSYOUNGGEN: 10082K->0K(89600K)] [PAROLDGEN: 32K->9638K(204800K)] 10114K->9638K(294400K),[METASPACE: 20158K->20156K(1067008K)], 0.0285388 SECS] [TIMES: USER=0.11 SYS=0.00, REAL=0.03 SECS]

2020-11-20T17:19:43.794-0800

日志打印时间日期格式如2013-05-04T21:53:59.234+0800

1.351

gc发生时，Java虚拟机启动以来经过的秒数

FULL GC (METADATA GC THRESHOLD)

发生了一次垃圾回收，这是一次FULL GC。它不区分新生代GC还是老年代GC。括号里的内容是gc发生的原因，这里的Metadata GC Threshold的原因是Metaspacel区不够用了。

Full GC(Ergonomics)：JVM自适应调整导致的GC

Full GC(System)：调用了System.gc()方法

[PSYOUNGGEN: 10082K->0K(89600K)]

PSYoungGen:表示GC发生的区域，区域名称与使用的GC收集器是密切相关的

Seriall收集器：Default New Generation显示DefNew
ParNewl收集器：ParNew
Parallel Scanvengel收集器：PSYoung
老年代和新生代同理，也是和收集器名称相关

10082K->0K(89600K):GC前该内存区域已使用容量 --> GC后该区域容量（该区域总容量）

如果是新生代，总容量则会显示整个新生代内存的9/10，即eden+from/to区
如果是老年代，总容量则是全部内存大小，无变化

[PAROLDGEN: 32K->9638K(204800K)]

老年代区域没有发生GC，因为本次GC是metaspace起的

10114K->9638K(294400K)

在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量 --> GC堆内存容量（堆内存总容量）堆内存总容量=9/10新生代+老年代<初始化的内存大小

[METASPACE: 20158K->20156K(1067008K)]

metaspace GC回收2K空间

0.0285388 SECS

整个GC所花费的时间，单位是秒

[TIMES: USER=0.11 SYS=0.00, REAL=0.03 SECS]

user：指的是CPU工作在用户态所花费的时间

sys：指的是CPU工作在内核态所花费的时间

rea：指的是在此次Gc事件中所花费的总时间

案例演示

代码

/**
 * 在jdk7 和 jdk8中分别执行
 *  * -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */
public class GCLogTest1 {
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
        testAllocation();
    }
}

图解

在JDK7中：与jdk8中有所不同

GC日志分析工具

上节介绍了GC日志的打印及含义，但是GC日志看起来比较麻烦，本节将会介绍一下GC日志可视化分析工具GCeasy和GCviewer等。通过GC日志可视化分析工具，我们可以很方便的看到JVM各个分代的内存使用情况、垃圾回收次数、垃圾回收的原因、垃圾回收占用的时间、吞吐量等，这些指标在我们进行JVM调优的时候是很有用的。

如果想把GC日志存到文件的话，是下面这个参数：-Xloggc:/path/to/gc.log 然后就可以用一些工具去分析这些gc日志。

GCeasy

GCeasy——一款超好用的在线分析GC日志的网站

官网地址：https://gceasy.io/，GCeasy是一款在线的GC日志分析器，可以通过GC日志分析进行内存泄漏检测、GC暂停原因分析、JVM配置建议优化等功能，而且是可以免费使用的（有一些服务是收费的）。