Java GC日志详解

Mark_Zoe
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）互相学习、互相交流。

avatar
文章
阅读
粉丝