第二十五章-分析GC日志

JVM java jvm

发布时间 : 2024-08-28 21:36

字数:3.3k 阅读 :

评论:

一、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日志格式

1. GC分类

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

1.1 部分收集

不是完整收集整个Java堆的垃圾收集。

其中又分为：

新生代收集（Minor GC/Young GC):只是新生代（Eden\S0,S1)的垃圾收集
老年代收集（Major GC/old GC):只是老年代的垃圾收集。
- 目前，只有CMSGC会有单独收集老年代的行为。
- 注意，很多时候Major GC会和Full GC混淆使用，需要具体分辨是老年代回收还是整堆回收。
混合收集（Mixed GC):收集整个新生代以及部分老年代的垃圾收集。
- 目前，只有G1GC会有这种行为

1.2 整堆收集（Full GC)

收集整个java堆和方法区的垃圾收集。

哪些情况会触发Full GC?

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

2. GC日志分类

2.1 MinorGC

MinorGC(或young GC或YGC)日志：

[GC (Allocation Failure) [PSYoungGen: 131584K->7195K(153088K)] 131584K->7203K(502784K), 0.0334432 secs] [Times: user=0.02 sys=0.00, real=0.04 secs]

minorGC日志解析

2.2 FullGC

[Full GC (Metadata GC Threshold) [PSYoungGen: 2848K->0K(158720K)] [ParOldGen: 32816K->19441K(349696K)] 35664K->19441K(508416K), [Metaspace: 34044K->34044K(1079296K)], 0.1156700 secs] [Times: user=0.09 sys=0.00, real=0.12 secs]

fullGC日志解析

3. GC日志结构剖析

3.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的原因是因为在年轻代中没有足够的空间能够存储新的数据了。

3.2 GC前后情况

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

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

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

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

3.3 GC时间

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

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

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

4. Minor GC 日志解析

2024-08-28T15:09:58.253+0800: 2.004: [GC (Allocation Failure) [PSYoungGen: 138937K->7465K(153088K)] 138945K->7473K(502784K), 0.0261046 secs] [Times: user=0.01 sys=0.00, real=0.03 secs]

2024-08-28T15:09:58.253+0800

日志打印时间日期格式
2.004

gc发生时，Java虚拟机启动以来经过的秒数
[GC (Allocation Failure)

发生了一次垃圾回收，这是一次MinorGC

它不区分新生代还是老年代GC，括号里的内容是gc发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能够存放需要分配的数据而失败
[PSYoungGen: 138937K->7465K(153088K)]
- PSYoungGen：表示GC发生的区域，区域名称与使用的GC收集器是密切相关的
  - Serial收集器：Default New Generation 显示Defnew
  - ParNew收集器：ParNew
  - Parallel Scanvenge收集器：PSYoung
  - 老年代和新生代同理，也是和收集器名称相关
- 138937K->7465K(153088K)：GC前该内存区域已使用容量->GC后该区域容量(该区域总容量)
  - 如果是新生代，总容量则会显示整个新生代内存的9/10，即eden+from/to区
  - 如果是老年代，总容量则是全身内存大小，无变化
138945K->7473K(502784K)

虽然本次是Minor GC，只会进行新生代的垃圾收集，但是也肯定会打印堆中总容量相关信息

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

整个GC所花费的时间，单位是秒
[Times: user=0.01 sys=0.00, real=0.03 secs]
- user：指CPU工作在用户态所花费的时间
- sys：指CPU工作在内核态所花费的时间
- real：指在此次事件中所花费的总时间

5. Full GC 日志解析

2024-08-28T15:10:01.578+0800: 5.329: [Full GC (Metadata GC Threshold) [PSYoungGen: 3264K->0K(163840K)] [ParOldGen: 6227K->7621K(349696K)] 9491K->7621K(513536K), [Metaspace: 20472K->20472K(1067008K)], 0.0627380 secs] [Times: user=0.04 sys=0.00, real=0.06 secs]

5.1 日志分解与解释

2024-08-28T15:10:01.578+0800: 5.329: [Full GC (Metadata GC Threshold) 
[PSYoungGen: 3264K->0K(163840K)] 
[ParOldGen: 6227K->7621K(349696K)] 
9491K->7621K(513536K), 
[Metaspace: 20472K->20472K(1067008K)], 
0.0627380 secs] 
[Times: user=0.04 sys=0.00, real=0.06 secs]

时间戳: 2024-08-28T15:10:01.578+0800
- 这表示日志条目的日期和时间。+0800 表示时区偏移量（例如，北京时间为 UTC+8）。
GC 事件触发时间: 5.329
- 表示从 JVM 启动到 GC 事件发生的时间，单位是秒。这表明在 JVM 启动后的 5.329 秒，发生了一个 Full GC。
GC 类型: [Full GC (Metadata GC Threshold)]
- Full GC 表示一次 Full Garbage Collection，即对整个堆（包括年轻代和老年代）进行的垃圾回收。
- Metadata GC Threshold 是此次 GC 的触发原因。它表明是因为元数据（如类的元信息）达到了特定的阈值，导致了 Full GC。
  - Full GC (Ergonomics) : JVM , 自适应调整导致的GC
  - Full GC(System) : 调用了System.gc()方法
年轻代回收: [PSYoungGen: 3264K->0K(163840K)]
- PSYoungGen: 使用 Parallel Scavenge（并行清除）垃圾回收器的年轻代（Young Generation）。
- 3264K->0K: 表示在回收前年轻代占用 3264 KB 内存，回收后占用 0 KB。
- (163840K): 年轻代的总容量是 163840 KB（160 MB）。
老年代回收: [ParOldGen: 6227K->7621K(349696K)]
- ParOldGen: 使用并行老年代垃圾回收器（Parallel Old Generation）。
- 6227K->7621K: 表示在回收前老年代占用 6227 KB 内存，回收后增加到 7621 KB。这通常表示有一些对象从年轻代晋升到老年代。
- (349696K): 老年代的总容量是 349696 KB（341.5 MB）。
堆总内存使用情况: 9491K->7621K(513536K)
- 9491K->7621K: 表示在 GC 前整个堆（年轻代 + 老年代）使用的总内存为 9491 KB，GC 后减少到 7621 KB。
- (513536K): 堆的总容量是 513536 KB（501.25 MB）。
元空间（Metaspace）: [Metaspace: 20472K->20472K(1067008K)]
- 20472K->20472K: 表示元空间（用于存储类的元数据）的使用量在 GC 前后保持不变，为 20472 KB。
- (1067008K): 元空间的总容量是 1067008 KB（1042 MB）。
GC 事件耗时: 0.0627380 secs
- 表示 GC 事件的总持续时间为 0.0627380 秒（约 62 毫秒）。
GC 时间分解: [Times: user=0.04 sys=0.00, real=0.06 secs]
- user=0.04: 用户态 CPU 时间（多个 CPU 线程的总和）是 0.04 秒。
- sys=0.00: 内核态 CPU 时间是 0.00 秒。
- real=0.06: 真实时间，即 GC 事件的墙钟时间是 0.06 秒。这个值通常比 user 和 sys 时间之和略大，反映了多线程并行执行的情况。

三、GC日志分析工具

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

如果想把GC日志存到文件的话，是下面这个参数：

-Xloggc:/path/to/gc.log
# 示例
java -Xms512m -Xmx512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/opt/module/ioms/ioms-ums/gc-%t.log -jar ioms-ums.jar --spring.profiles.active=dev

然后就可以用一些工具去分析这些gc日志。

示例代码1

/**
 * 测试生成详细的日志文件
 *
 * -Xms60m -Xmx60m -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:d:/gc-log-%t.log
 *
 */
public class GCLogTest {
    public static void main(String[] args) {
        ArrayList<byte[]> list = new ArrayList<>();

        for (int i = 0; i < 5000; i++) {
            byte[] arr = new byte[1024 * 50];//50KB
            list.add(arr);
            try {
                Thread.sleep(30);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }

    }
}

示例代码2

/**
 * java.lang.OutOfMemoryError: Metaspace异常演示：
 *
 * -Xms60m -Xmx60m -XX:MetaspaceSize=10m -XX:MaxMetaspaceSize=10m -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:d:/meta-log-%t.log
 *
 */
public class MetaspaceOOM extends ClassLoader {
    public static void main(String[] args) {
        int j = 0;
        try {
            MetaspaceOOM test = new MetaspaceOOM();
            for (int i = 0; i < 10000; i++) {
                //创建ClassWriter对象，用于生成类的二进制字节码
                ClassWriter classWriter = new ClassWriter(0);
                //指明版本号，修饰符，类名，包名，父类，接口
                classWriter.visit(Opcodes.V1_8, Opcodes.ACC_PUBLIC, "Class" + i, null, "java/lang/Object", null);
                //返回byte[]
                byte[] code = classWriter.toByteArray();
                //类的加载
                test.defineClass("Class" + i, code, 0, code.length);//Class对象
                j++;
            }
        } finally {
            System.out.println(j);
        }
    }
}

1. GCeasy

基本概述

GCeasy——一款超好用的在线分析GC日志的网站官网地址：https://gceasy.io/gc-dashboard.jsp

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

GCeasy官网

分析结果

内存分析

gc时间分析

堆的使用

GC统计

等等……

2. GCViewer

2.1 基本概述

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

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

2.2 安装

下载GCViewer工具

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

2.3 启动GCViewer(gui)

需双击 gcviewer-1.3x.jar

或

需要运行java1.8 vm

java -jar gcviewer-1.3x.jar

GCViewer

很难用！！！

3. 其他工具

3.1 GChisto

GChisto 是一款专业分析gc日志的工具，可以通过gc日志来分析 : MinorGC、Full GC的次数、频率、持续时间等，通过列表、报表、图表等不同形式来反应gc的情况。

虽然界面略显粗糙，但是功能还是不错的。

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

3.2 HPjmeter

工具很强大，但只能打开由以下参数生成的 GC log , -verbose:gc -Xloggc:gc.log 。添加其他参数生成的 gc.log无法打开

HPjmeter集成了以前的 HPjtune 功能，可以分析在HP机器上产生的垃圾回收日志文件

转载请注明来源，欢迎对文章中的引用来源进行考证，欢迎指出任何有错误或不够清晰的表达。可以在下面评论区评论，也可以邮件至 george_95@126.com