Java GC日志详解

2,741 阅读9分钟

“这是我参与更文挑战的第8天,活动详情查看: 更文挑战

上篇介绍了JVM运行时参数,接下来介绍Java GC日志。

一、GC日志参数

-verbose:gc

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

-XX:+PrintGC

等同于-verbose:gc表示打开简化的GC日志

-XX:+PrintGCDetails

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

-XX:+PrintGCTimeStamps

输出GC发生时的时间戳

-XX:+PrintGCDateStamps

输出GC发生时的时间戳(以日期的形式,如2021-06-15T14:23:59.234+0800)

-XX:+PrintHeapAtGC

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

-Xloggc:<file>

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

二、GC日志格式

GC分类

针对HotSpot VM的实现,它里面的GC按照回收区域又分为两大种类类型:一种是部分收集(Parial GC),一种是整堆收集(Full GC)。

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

  1. 新生代收集(Minor GC / Young GC):只是新生代(Eden\S0,S1)的垃圾收集
  2. 老年代收集(Major GC / Old GC):只是老年代的垃圾收集。
    • 目前,只有CMS GC会单独收集老年代的行为。
    • 注意,很多时候Major GC会和Full GC混淆使用,需要具体分辨是老年代回收还是整堆回收。
  3. 混合收集(Mixed GC):收集整个新生代以及部分老年代的垃圾收集。
    • 目前,只有G1 GC会有这种行为 整堆收集(Full GC):收集整个Java堆和方法区的垃圾收集。

哪些情况会触发Full GC?

  1. 老年代空间不足
  2. 方法区空间不足
  3. 显式调用System.gc()
  4. Minor GC进入老年代的数据的平均大小大于老年代的可用内存
  5. 大对象直接进入老年代,而老年代的可用空间不足

GC日志分类

MinorGC

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

FullGC

image.png

GC日志结构剖析

垃圾收集器

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

GC前后情况

通过图示,我们可以发现GC日志格式的规律一般都是:GC前内存占用->GC后内存占用(该区域内存总大小) [PSYoungGen: 5986k->696k(8704k)] 5986k->704k(9216k)

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

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

GC时间

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

  1. user:进程执行用户态代码(核心之外)所使用的时间。这是执行此进程所使用的实际CPU时间,其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下,表示GC线程执行所使用的CPU总时间。
  2. sys:进程在内核态消耗的CPU时间,即在内核执行系统调动或等待系统事件所使用的CPU时间
  3. 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)]

  1. PSYoungGen:表示GC发生的区域,区域名称与使用的GC收集器是密切相关的
    • Serial收集器:Default New Generation显示DefNew
    • ParNew收集器:ParNew
    • Parallel Scanvenge收集器:PSYoung
    • 老年代和新生代同理,也是和收集器名称相关
  2. 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]

  1. user:指的是CPU工作在用户态所花费的时间
  2. sys:指的是CPU工作在内核态所花费的时间
  3. real:指的是在此次GC事件中所花费的总时间

Full GC 日志剖析

2020-11-20T17:19:43.794-0800: 1.351: [FULL GC (METADATA 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)

  1. 发生了一次垃圾回收,这是一次FULL GC。它不区分新生代GC还是老年代GC
  2. 括号里的内容是gc发生的原因,这里的Metadata GC Threshold的原因是Metaspace区不够用了。
    • Full GC(Ergonomics):JVM自适应调整导致的GC
    • Full GC(System):调用了System.gc()方法

[PSYoungGen: 10082k->0k(89600k)]

  1. PSYoungGen:表示GC发生的区域,区域名称与使用的GC收集器是密切相关的
    • Serial收集器:Default New Generation显示DefNew
    • ParNew收集器:ParNew
    • Parallel Scanvenge收集器:PSYoung
    • 老年代和新生代同理,也是和收集器名称相关
  2. 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]

  1. user:指的是CPU工作在用户态所花费的时间
  2. sys:指的是CPU工作在内核态所花费的时间
  3. real:指的是在此次GC事件中所花费的总时间

三、GC日志分析工具

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

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

GCeasy

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

官网地址:gceasy.io/,GCeasy是一款在…

GCViewer

上面介绍了一款在线的GC日志分析器,下面介绍一个离线版的GCViewer。

GCViewer是一个免费的、开源的分析小工具,用于可视化查看由SUN/Oracle,IBM,HP和BEA Java虚拟机产生的垃圾收集器的日志。

GCViewer用于可视化Java VM选项-verbose:gc和.NET生成的数据-Xloggc:<file>。它还计算与垃圾回收相关的性能指标(吞吐量,累积的暂停,最常的暂停等)。

下载GCViewer工具

  1. 源码下载:github.com/chewiebug/G…
  2. 运行版本下载:github.com/chewiebug/G…

只需双击gcviewer-1.3x.jar或运行java jar gcviewer-1.3x.jar(它需要运行Java 1.8vm),即可启动GCViewer(gui)

四、总结

本节介绍了Java GC日志分析,GC日志参数、GC日志格式、GC日志分析工具,希望大家能有所收获~ 下一篇将介绍OOM常见各各种场景及解决方案。

欢迎大家关注公众号(MarkZoe)互相学习、互相交流。