JVM24-分析GC日志

913 阅读9分钟

欢迎大家关注 github.com/hsfxuebao/j… ,希望对大家有所帮助,要是觉得可以的话麻烦给点一下Star哈

1. GC日志参数

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

-verbose:gc

输出GC日志。类似:-verbose:gc

-XX:+PrintGC

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

-XX:+PrintGCDetails

输出GC发生时的时间截

-XX:+PrintGCTimeStamps

输出GC发生时的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)

-XX:+PrintGCDateStamps

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

-XX:+PrintHeapAtGC

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

 -Xloggc:<file>

2. GC日志格式

复习:GC分类

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

部分收集

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

其中又分为:

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

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

    • 目前,只有CMSGC会有单独收集老年代的行为。
    • 注意,很多时候Major GC会和Full GC混淆使用,需要具体分辨是老年代回收还是整堆回收。
  • 混合收集(Mixed GC):收集整个新生代以及部分老年代的垃圾收集。

    • 目前,只有G1GC会有这种行为

整堆收集(Full GC)

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

哪些情况会触发Full GC?

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

GC日志分类

MinorGC

MinorGC(或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]

在这里插入图片描述

在这里插入图片描述

FullGC

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]

在这里插入图片描述

在这里插入图片描述

GC日志结构剖析

垃圾收集器

  • 使用 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前后情况

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

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

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

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

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不够用。

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

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

0.822:

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

它不区分新生代GC 还是老年代GC , 括号里的内容是gc发生的原因,这里的Allocang分配的数据而失败。

[GC(Allocation Failure)

GC发生的区域,区域名称与使用的GC

Serial收集器:Default New Generation 显示DefNew
ParNew收集器:ParNew
Parallel Scanvenge收集器:PSYoung
老年代和新生代同理,也是和收集器名称相关

PSYoungGen:

前该内存区域已使用容量 -> GC后该区域容量(该区域总容量)

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

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

76800K-8433K(89600K):GC

前堆内存已使用容量 -> GC堆内存容量(堆内存总容量)

在显示完区域容量GC的情况之后,会接着显示整个堆内存区域的GC情况:GC

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

76800K-8449K(294400K)

整个GC所花费的时间,单位是秒

,0.0088371 secs]

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

[Times:user=0.02 sys=0.01,real=0.01 secs]

FullGC日志解析

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

gc发生时,Janndean以来经过的的数

1.351

发生了一次垃圾回收,这是一次FULLGC

它不区分新生代GC还是老年代GC

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

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

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

Full GC (Metadata GC Threshold)

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

Seria收集器:Default New Generation 显示DefNew
ParNew收集器:ParNew
Parallel Scanvenge收集器:PSYoung
老年代和新生代同理,也是和收集器名称相关

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

前该内存区域已使用容量-GC后该区域容量(该区域总容量)

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

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

10082K->0K(89600K):GC

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

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

GC前堆内存已使用容量-GC堆内存容量(堆内存总容量)

在显示完区域容量GC的情况之后,会接着显示整个堆内存区域的GC情况:

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

10114K-9638K(294400K).

metaspaceGC回收2K空间

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

整个GC所花费的时间,单位是秒

0.0285388secs

[Times:user=0.11 sys=0.00,real=0.03 secs]

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

3. GC日志分析工具

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

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

-Xloggc:/path/to/gc.log

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

/**
 * 测试生成详细的日志文件
 *
 * -Xms60m -Xmx60m -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC
 *
 */
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();
            }
        }

    }
}

/**
 * java.lang.OutOfMemoryError: Metaspace异常演示:
 *
 * -Xms60m -Xmx60m -XX:MetaspaceSize=10m -XX:MaxMetaspaceSize=10m -XX:SurvivorRatio=8 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC
 *
 */
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);
        }
    }
}

GCeasy

基本概述

GCeasy——一款超好用的在线分析GC日志的网站官网地址:

gceasy.io/gc-index.js…

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

在这里插入图片描述

GCViewer

基本概述

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

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

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

安装

1.下载GCViewer工具

源码下载:github.com/chewiebug/G…

运行版本下载:github.com/chewiebug/G…

启动GCViewer(gui)

需双击 gcviewer-1.3x.jar

需要运行java1.8 vm

java -jar gcviewer-1.3x.jar

其他工具

GChisto

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

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

官网上没有下载的地方,需要自己从SVN上拉下来编译

不过这个工具似乎没怎么维护了,存在不少bug

HPjmeter

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

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

参考:blog.csdn.net/qq\_4422609…