Young Kbt blog
Young Kbt
2022-02-01
目录

JVM - 分析GC日志

# GC 分类

针对 HotSpot VM 的实现，它里面的 GC 按照回收区域又分为两大种类型：一种是部分收集（Partial GC），一种是整堆收集（Full GC）

  • 部分收集（Partial GC）：不是完整收集整个 Java 堆的垃圾收集。其中又分为：

    • 新生代收集（Minor GC / Young GC）：只是新生代（Eden / S0，S1）的垃圾收集
    • 老年代收集（Major GC / Old GC）：只是老年代的垃圾收集。目前，只有 CMS GC 会有单独收集老年代的行为。注意，很多时候 Major GC 会和 Full GC 混淆使用，需要具体分辨是老年代回收还是整堆回收

  • 混合收集（Mixed GC）：收集整个新生代以及部分老年代的垃圾收集。目前，只有 G1 GC 会有这种行为

  • 整堆收集（Full GC）：收集整个 java 堆和方法区的垃圾收集

哪些情况会触发 Full GC？

  • 老年代空间不足

  • 方法区空间不足

  • 显式调用 System.gc()

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

  • 大对象直接进入老年代，而老年代的可用内存不足

# GC 日志分类

Minor GC

Minor GC（或 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]
1

image-20220201230156081

image-20210506202156090

Full GC

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

image-20220201230218472

image-20210506202349072

# GC 日志结构剖析

# 透过日志看垃圾收集器

  • Serial 收集器：新生代显示 "[DefNew"，即 Default New Generation

  • ParNew 收集器：新生代显示 "[ParNew"，即 Parallel New Generation

  • Parallel Scavenge 收集器：新生代显示 "[PSYoungGen"，JDK1.7 使用的即 PSYoungGen

  • Parallel Old 收集器：老年代显示 "[ParoldGen"

  • G1 收集器：显示 "garbage-first heap"

# 透过日志看GC原因

  • Allocation Failure：表明本次引起 GC 的原因是因为新生代中没有足够的区域存放需要分配的数据
  • Metadata GCThreshold：Metaspace 区不够用了
  • FErgonomics：JVM 自适应调整导致的 GC
  • System：调用了 System.gc() 方法

# 透过日志看GC前后情况

通过图示，我们可以发现 GC 日志格式的规律一般都是：GC 前内存占用 -＞ GC 后内存占用（该区域内存总大小）

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

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

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

注意：Minor GC 堆内存总容量 = 9/10 年轻代 + 老年代。原因是 Survivor 区只计算 from 部分，而 JVM 默认年轻代中 Eden 区和 Survivor 区的比例关系，Eden:S0:S1=8:1:1。

# 透过日志看GC时间

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

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

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

# Minor GC日志分析

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

分析上方代码块的 Minor GC 日志：

  • 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 Scanvenge 收集器：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 工作在内核态所花费的时间
    • real：指的是在此次 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]
1
2
3
4
5

分析上方代码块的 Full GC 日志：

  • 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 发生的原因，这里的 MetadataGC Threshold 的原因是 Metaspace 区不够用了
      • Full GC (Ergonomics)：JVM 自适应调整导致的 GC
      • Full GC (System)：调用了 System.gc() 方法

  • [PSYoungGen: 10082K->0K(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 引起的

  • 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 工作在内核态所花费的时间
    • real：指的是在此次 GC 事件中所花费的总时间

# GC 日志分析工具

GCEasy

官网地址：https://gceasy.io/

GCEasy 是一款在线的 GC 日志分析器，可以通过 GC 日志分析进行内存泄露检测、GC 暂停原因分析、JVM 配置建议优化等功能，大多数功能是免费的。

GCViewer

源码下载：https://github.com/chewiebug/GCViewer

运行版本下载：https://github.com/chewiebug/GCViewer/wiki/Changelog

GCViewer 是一款离线的 GC 日志分析器，用于可视化 Java VM 选项 -verbose:gc 和 .NET 生成的数据 -Xloggc:<file>。还可以计算与垃圾回收相关的性能指标（吞吐量、累积的暂停、最长的暂停等）。当通过更改世代大小或设置初始堆大小来调整特定应用程序的垃圾回收时，此功能非常有用。

GChisto

  • 官网上没有下载的地方，需要自己从 SVN 上拉下来编译
  • 不过这个工具似乎没怎么维护了，存在不少 bug

HPjmeter

  • 工具很强大，但是只能打开由以下参数生成的 GC log，-verbose:gc -Xloggc:gc.log。添加其他参数生成的 gc.log 无法打开
  • HPjmeter 集成了以前的 HPjtune 功能，可以分析在 HP 机器上产生的垃圾回收日志文件
编辑此页 (opens new window)
#Java
更新时间: 2024/11/02, 18:07:00
JVM - 运行时参数
Java8 - 新特性

← Java8 - 新特性→

最近更新
01
技术随笔 - Element Plus 修改包名 原创
11-02
02
Reactor - 扩展性
11-02
03
Reactor - 最佳实践
11-02
更多文章>
Theme by Vdoing | Copyright © 2021-2024 Young Kbt | blog
桂ICP备2021009994号