GC日志分析

GC分类

针对HotSpot VM的实现,它里面的GC按照回收区域又分为两大种类型:

一种是部分收集(Partial GC) ，一种是整堆收集(Full GC)。

• 部分收集:不是完整收集整个Java堆的垃圾收集。其中又分为:

  • 新生代收集(Minor Gc / Young GC) :只是新生代(Eden\S0,S1)的垃圾收集

  • 老年代收集(Major Gc / 0ld GC) :只是老年代的垃圾收集。

    • 目前,只有CMS GC会有单独收集老年代的行为。

    • 注意,很多时候Major GC会和Fu11 Gc混淆使用,需要具体分辨是老年代同收还是整堆回收。

  • 混合收集(Mixed GC):收集整个新生代以及部分老年代的垃圾收集。

    • 目前,只有G1 GC会有这种行为

• 整堆收集(Full GC):收集整个java堆和方法区的垃圾收集。

哪些情况会触发Full GC

• 老年代空间不足

• 方法区空间不足

• 显示调用Sytem.gc()

• Minor GC进入老年代的数据的平均大小>老年代可用内存

• 大对象直接进入老年代，导致老年代的可用空间不足

GC日志结构

垃圾收集器

[Full GC (Ergonomics) [PSYoungGen: 16344K->5500K(18432K)] [ParOldGen: 30298K->40800K(40960K)] 46642K->46301K(59392K), [Metaspace: 3993K->3993K(1056768K)], 0.0064641 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

图1

补充：

• 使用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 (Allocation Failure) [PSYoungGen: 16303K->2016K(18432K)] 16303K->14198K(59392K), 0.0040885 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

GC前后情况

分块规律（每个[]）

图2

[PSYoungGen: 16303K->2016K(18432K)] 16303K->14198K(59392K), 0.0040885 secs] 

中括号内: G回收前年轻代堆大小,回收后大小, (年轻代堆总大小)

括号外: GC回收前年轻代和老年代大小,回收后大小, (年轻代和老年代总大小)

GC时间

[GC (Allocation Failure) [PSYoungGen: 16303K->2016K(18432K)] 16303K->14198K(59392K), 0.0040885 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

GC日志中有三个时间: user, sys和real

• user-进程执行用户态代码(核心之外)所使用的时间。这是执行此进程所使用的实际CPU时间,其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下,表示GC线程执行所使用的CPU总时间。

• sys-进程在内核态消耗的CPU时间,即在内核执行系统调用或等待系统事件所使用的CPU时间

• real-程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间(比如等待1/0完成) 。对于并行gc,这个数字应该接近(用户时间+系统时间)除以垃圾收集器使用的线程数。

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

Minor GC日志解析

2021-01-30T15:01:12.596+0800: [GC (Allocation Failure) [PSYoungGen: 16303K->2020K(18432K)] 16303K->14154K(59392K), 0.0051686 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

0.822: [GC (Allocation Failure) [PSYoungGen: 116303K->2020K(18432K)] 76800K->8449K(294400K), 0.0033008 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

前面打印时间，默认是没有的，需要开启-XX:+PrintGCDateStamps -XX:+PrintGCDetails。

前面打印执行时间，是因为配置了-XX:+PrintGCTimeStamps -XX:+PrintGCDetails

下面对以上日志进行解析：

• 2020-11-20T17:19:43.265-08002013-05-04T21:53:59.234+08000：

  • 日志打印时间日期格式如2020-11-20T17:19:43.265-08002013-05-04T21:53:59.234+0800

• 0.822:

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

• [GC (Allocation Failure)：

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

• [PSYoungGen: 16303K->2020K(18432K)] :

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

    • Serial收隼器: Default New Generation显示DefNew

    • ParNew收集器: ParNew

    • Parallel Scanvenge收集器: PSYoung

    • 老年代和新生代同理,也是和收集器名称相关

  • 76800K->8433K(89600K)：GC前该内存区域已使用容量->G后该区域容量(该区域总容量)

    • 如果是新生代,总容量则会显示整个新生代内存的9/10,即eden from/to 区

    • 如果是老年代,总容量则是全部内存大小,无变化

• 76800K->8449K(294400K)

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

• 0.0088371 secs)整个GC所花费的时间,单位是秒

• [Times: user=0.00 sys=0.00, real=0.01 secs]

  • user-进程执行用户态代码(核心之外)所使用的时间。

  • sys-进程在内核态消耗的CPU时间。

  • real-程序从开始到结束所用的时钟时间。

FullGC日志解析

9.619: [Full GC (Ergonomics) [PSYoungGen: 10082K->0K(89600K)] [ParOldGen: 32K->9638K(204800K)] 10114K->9638K(294400K), [Metaspace: 20158K->20156K(1067008K)], 0.0111210 secs] [Times: user=0.16 sys=0.00, real=0.02 secs] 

2021-01-30T15:01:17.856+0800: [Full GC (Ergonomics) [PSYoungGen: 2036K->0K(18432K)] [ParOldGen: 28444K->30303K(40960K)] 30480K->30303K(59392K), [Metaspace: 3993K->3993K(1056768K)], 0.0161352 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

下面对以上日志进行解析：

• 2020-11-20T17:19:43.265-08002013-05-04T21:53:59.234+08000：

  • 日志打印时间日期格式如2020-11-20T17:19:43.265-08002013-05-04T21:53:59.234+0800

• 9.619:

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

• Full GC (Metadata GC Threshald):

  • 发生了一次垃圾回收,这是一次FULL GC它不区分新生代GC还是老年代GC

  • 括号里的内容是gc发生的原因,这里的MetadataGC Threshold的原因是Metaspace区不够用了

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

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

• PSYoung[PSYoungGen: 10082K->OK(89600K):

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

    • Serial收集器：Default New Generation 显示 DefNew

    • ParNew收集器: ParNew

    • Parallel Scanvenge收集器: PSYoung

    • 老年代和新生代同理,也是和收集器名称相关

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

    • 如果是新生代,总容量则会显示整个新生代内存的9/10,即eden-from/to 区

    • 如果是老年代,总容量则是全部内存大小,无变化

• [ParOldGen: 32K->9638K(204800K)

  • 老年代区域没有发生GC,因为本次GC是metaspace引l起的

• 10114K->9638K(294400K)：

  • 在显示完区域容量GC的情况之后,会接着显示整个堆内存区域的GC情况:GC前堆内存已使用容量-> GC堆内存容量(堆内存总容量)

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

• [Metaspace: 20158K->20156K(1067008K)]：

  • metaspace GC 回收2k空间

• 0.0088371 secs)整个GC所花费的时间,单位是秒

• [Times: user=0.00 sys=0.00, real=0.01 secs]

  • user-进程执行用户态代码(核心之外)所使用的时间。

  • sys-进程在内核态消耗的CPU时间。

  • real-程序从开始到结束所用的时钟时间。

在线分析工具

GC easy

例子：

元空间溢出

image.png

Peak出现溢出前（顶峰）最后一次占用情况的快照。

这里是元空间溢出，可以看见巅峰前，元空间的占用。

老年代溢出

image.png

吞吐量和gc耗时

image.png

直方图

image.png

老年代oom

image.png