Rubin's Blog

  • 首页
  • 关于作者
  • 隐私政策
享受恬静与美好~~~
分享生活的点点滴滴~~~
  1. 首页
  2. JVM
  3. 正文

JVM之GC日志分析

2022年 1月 4日 1009点热度 0人点赞 0条评论

GC日志是一个很重要的工具,它准确记录了每一次的GC的执行时间和执行结果,通过分析GC日志可以优化堆设置和GC设置,或者改进应用程序的对象分配模式。

GC日志参数

不同的垃圾收集器,输出的日志格式各不相同,但也有一些相同的特征。熟悉各个常用垃圾收集器的GC日志,是进行JVM调优的必备一步。 解析GC日志,首先需要收集日志,常用的有以下JVM参数用来打印输出日志信息:

GC日志参数

如,使用如下参数启动:

-Xms28m
-Xmx28m
//开启记录GC日志详细信息(包括GC类型、各个操作使用的时间),并且在程序运行结束打印出JVM的内存占用情况
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+UseGCLogFileRotation      开启滚动生成日志
-Xloggc:E:/logs/gc.log

常用垃圾收集器参数

GC日志分析

日志的含义

GC日志理解起来十分简单,因为日志本来就是要给开发人员看的,所以设计的很直观。

举个例子,我们来分别说明各个部分所代表的含义:

[GC (Allocation Failure) [PSYoungGen: 6146K->904K(9216K)] 6146K->5008K(19456K), 0.0038730
 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]

将上面 GC 日志抽象为各个部分,然后我们再分别说明各个部分的含义:

[a(b)[c:d->e(f), g secs] h->i(j), k secs] [Times: user:l sys=m, real=n secs]
a: GC 或者是 Full GC
b: 用来说明发生这次 GC 的原因
c: 表示发生GC的区域,这里表示是新生代发生了GC,上面那个例子是因为在新生代中内存不够给新对象分配了,然后触发了 GC
d: GC 之前该区域已使用的容量
e: GC 之后该区域已使用的容量
f: 该内存区域的总容量
g: 表示该区域这次 GC 使用的时间
h: 表示 GC 前整个堆的已使用容量
i: 表示 GC 后整个堆的已使用容量
j: 表示 Java 堆的总容量
k: 表示 Java堆 这次 GC 使用的时间
l: 代表用户态消耗的 CPU 时间
m: 代表内核态消耗的 CPU 时间
n: 整个 GC 事件从开始到结束的墙钟时间(Wall Clock Time)

使用 ParNew + Serial Old 的组合进行内存回收

设置JVM参数:

-Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:SurvivorRatio=8

测试代码:

public class TestGCLog01 {
    private static final int _1MB = 1024*1024;
    /**
     * VM参数:
     *  1.  -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     */
    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2*_1MB];
        allocation2 = new byte[2*_1MB];
        allocation3 = new byte[2*_1MB];
        allocation4 = new byte[4*_1MB];
    }

    public static void main(String[] args) {
        testAllocation();
    }
}

打印结果:

[GC (Allocation Failure) [ParNew: 6146K->753K(9216K), 0.0065877 secs] 6146K->4849K(19456K),
0.0092108 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
Heap
par new generation total 9216K, used 7220K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
eden space 8192K, 78% used [0x00000000fec00000, 0x00000000ff250ea0, 0x00000000ff400000)
from space 1024K, 73% used [0x00000000ff500000, 0x00000000ff5bc488, 0x00000000ff600000)
to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
tenured generation total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
the space 10240K, 40% used [0x00000000ff600000, 0x00000000ffa00020, 0x00000000ffa00200,
0x0000000100000000)
Metaspace used 3362K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 369K, capacity 388K, committed 512K, reserved 1048576K
Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old
collector is deprecated and will likely be removed in a future release

结果分析:

通过上面的GC日志我们可以看出一开始出现了 MinorGC, 引起GC的原因是 内存分配失败 ,因为分配allocation的时候,Eden区已经没有足够的区域来分配了,所以发生来本次 MinorGC ,经过 MinorGC 之后新生代的已使用容量从6146K->753K,然而整个堆的内存总量却几乎没有减少,原因就是,由于发现新生代没有可以回收的对象,所以不得不使用内存担保将allocation1~3 三个对象提前转移到老年代。此时再在 Eden 区域为 allocation 分配 4MB 的空间,因此最后我们发现 Eden 区域占用了 4MB,老年代占用了 6MB。

使用 Parallel Scavenge + Parallel Old 的组合进行内存回收

设置参数:

-Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+PrintGCDetails -XX:SurvivorRatio=8

测试代码:

public class TestGCLog02 {
    private static final int _1MB = 1024*1024;
    /**
     * VM参数:
     *  2. -Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
     */
    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2*_1MB];
        allocation2 = new byte[2*_1MB];
        allocation3 = new byte[2*_1MB];
        allocation4 = new byte[4*_1MB]; //出现一次 Minor GC
    }

    public static void main(String[] args) {
        testAllocation();
    }
}

执行结果:

[GC (Allocation Failure) [PSYoungGen: 6146K->872K(9216K)] 6146K->4976K(19456K), 0.0138583 secs]
[Times: user=0.06 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 9216K, used 7339K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
eden space 8192K, 78% used [0x00000000ff600000,0x00000000ffc50e68,0x00000000ffe00000)
from space 1024K, 85% used [0x00000000ffe00000,0x00000000ffeda020,0x00000000fff00000)
to space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
ParOldGen total 10240K, used 4104K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
object space 10240K, 40% used [0x00000000fec00000,0x00000000ff002020,0x00000000ff600000)
Metaspace used 3420K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 371K, capacity 388K, committed 512K, reserved 1048576K

大对象回收分析

大对象直接进入老年代 虚拟机提供一个参数 -XX:PretenureSizeThreshold 用来设置直接在老年代分配的对象的大小,如果对象大于这个值就会直接在老年代分配。这样做的目的是避免在 Eden 区及两个Survivor 区之间发生大量的内存复制。

设置参数:

-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -
XX:PretenureSizeThreshold=3145728

测试代码:

public class TestGCLog03 {
    private static final int _1MB = 1024 * 1024;

    /**
     * VM参数:(参数序号对应实验序号)
     *  -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:PretenureSizeThreshold=3145728
     */
    public static void testPreteureSizeThreshold() {
        byte[] allocation;
        allocation = new byte[4 * _1MB];
    }

    public static void main(String[] args) {
        testPreteureSizeThreshold();
    }
}

执行结果:

Heap
par new generation total 9216K, used 2214K [0x00000000fec00000, 0x00000000ff600000,
0x00000000ff600000)
eden space 8192K, 27% used [0x00000000fec00000, 0x00000000fee29be8, 0x00000000ff400000)
from space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
to space 1024K, 0% used [0x00000000ff500000, 0x00000000ff500000, 0x00000000ff600000)
tenured generation total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000,
0x0000000100000000)
the space 10240K, 40% used [0x00000000ff600000, 0x00000000ffa00010, 0x00000000ffa00200,
0x0000000100000000)
Metaspace used 3430K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 373K, capacity 388K, committed 512K, reserved 1048576K

结果分析:

过上面的堆的内存占用情况很容易看出我们分配的4MB大小的对象直接被放到了老年代。

日志分析工具

日志工具简介

GC日志可视化分析工具GCeasy和GCviewer。通过GC日志可视化分析工具,我们可以很方便的看到JVM各个分代的内存使用情况、垃圾回收次数、垃圾回收的原因、垃圾回收占用的时间、吞吐量等,这些指标在我们进行JVM调优的时候是很有用的。

  • GCeasy是一款在线的GC日志分析器,可以通过GC日志分析进行内存泄露检测、GC暂停原因分析、JVM配置建议优化等功能,而且是可以免费使用(在线分析工具:https://gceasy.io/index.jsp)
  • GCViewer是一款实用的GC日志分析软件,免费开源使用,你需要安装jdk或者java环境才可以使用。软件为GC日志分析人员提供了强大的功能支持,有利于大大提高分析效率

测试准备

编写代码生成gc.log日志准备分析:

public class TestGCLog04 {
    private static final int _1MB = 1024 * 1024;

    /**
     * -XX:SurvivorRatio=8 -XX:+UseParallelGC -XX:+UseParallelOldGC  -XX:+PrintGCDetails -Xloggc:D://logs/gc.log
     */
    public static void main(String[] args) {
        ArrayList<byte[]> list = new ArrayList<byte[]>();
        for (int i = 0; i < 2000; i++) {
            byte[] arr = new byte[1024 * 1024];
            list.add(arr);
            try {
                Thread.sleep(20);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

在d:/logs/gc.log 生成日志:

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) for windows-amd64 JRE (1.8.0_162-b12), built on Dec
19 2017 20:00:03 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16454268k(6068260k free), swap 32906696k(20647740k free)
CommandLine flags: -XX:InitialHeapSize=104857600 -XX:MaxHeapSize=104857600 -XX:+PrintGC -
XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -
XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
5.291: [GC (Allocation Failure) [PSYoungGen: 27642K->3064K(30720K)] 27642K->24839K(99328K),
0.2011370 secs] [Times: user=0.64 sys=0.01, real=0.20 secs]
Heap
PSYoungGen total 30720K, used 29578K [0x00000000fdf00000, 0x0000000100000000,
0x0000000100000000)
eden space 27648K, 95% used [0x00000000fdf00000,0x00000000ff8e4748,0x00000000ffa00000)
from space 3072K, 99% used [0x00000000ffa00000,0x00000000ffcfe1b0,0x00000000ffd00000)
to space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
ParOldGen total 68608K, used 21775K [0x00000000f9c00000, 0x00000000fdf00000,
0x00000000fdf00000)
object space 68608K, 31% used [0x00000000f9c00000,0x00000000fb143d50,0x00000000fdf00000)
Metaspace used 3947K, capacity 4568K, committed 4864K, reserved 1056768K
class space used 434K, capacity 460K, committed 512K, reserved 1048576K

GCeasy

这是一个在线分析日志的工具,主要功能是免费的,存在部分收费,地址:https://gceasy.io/。

把我们生成的日志文件,上传分析,就会接到可视化界面:

jvm堆

Allocated:各部分分配大小。

Peak:峰值内存使用量。

关键绩效指标

吞吐量:93.769%,运行应用程序的时间/(GC时间的比值+运行应用程序的时间)。

平均GC停顿时间。

最大GC停顿时间。

GC停顿持续时间范围:时间范围、GC数量、百分比。

交互式图表

左边菜单有很多:

GC之前的堆、GC之后的堆、GC持续时间、GC停顿持续时间、回收的内存字节、Young区内存变化、Old区内存变化、Metaspace内存变化、分配对象大小、对象从Young到Old内存大小变化。

后序的内容有:GC统计信息、Minor GC/Full GC信息、内存泄漏、GC的原因等等,所以这个工具的功能真的很强大。

我们可以对比一下,Parallel、CMS、G1的GC效率。

GCViewer

GCViewer是一个小工具,可以可视化展示 生成的详细GC输出。支持Sun / Oracle,IBM,HP和BEA的Java虚拟机。它是GNU LGPL下发布的免费软件。

下载:https://sourceforge.net/projects/gcviewer/。

使用简介:

java -jar gcviewer-1.37-SNAPSHOT.jar

打开之后,点击File->Open File打开我们的GC日志,可以看到如下图,图标是可以放大缩小的,主要内容就是红线8圈住的部分,里面的内容跟上面的GCeasy的比较类似,具体的可以看下GitHub中的描述。

以上就是本文的全部内容。欢迎各位小伙伴积极留言交流~~~

本作品采用 知识共享署名 4.0 国际许可协议 进行许可
标签: JVM
最后更新:2022年 6月 9日

RubinChu

一个快乐的小逗比~~~

打赏 点赞
< 上一篇
下一篇 >

文章评论

razz evil exclaim smile redface biggrin eek confused idea lol mad twisted rolleyes wink cool arrow neutral cry mrgreen drooling persevering
取消回复
文章目录
  • GC日志参数
    • GC日志参数
    • 常用垃圾收集器参数
  • GC日志分析
    • 日志的含义
    • 使用 ParNew + Serial Old 的组合进行内存回收
    • 使用 Parallel Scavenge + Parallel Old 的组合进行内存回收
    • 大对象回收分析
  • 日志分析工具
    • 日志工具简介
    • 测试准备
    • GCeasy
      • jvm堆
      • 关键绩效指标
      • 交互式图表
    • GCViewer
最新 热点 随机
最新 热点 随机
问题记录之Chrome设置屏蔽Https禁止调用Http行为 问题记录之Mac设置软链接 问题记录之JDK8连接MySQL数据库失败 面试系列之自我介绍 面试总结 算法思维
数据结构之树 JVM调优实战 SpringCloud之Config分布式配置中心 Docker之私服安装 面试系列之自我介绍 MySQL之Sharding-JDBC编排治理剖析

COPYRIGHT © 2021 rubinchu.com. ALL RIGHTS RESERVED.

Theme Kratos Made By Seaton Jiang

京ICP备19039146号-1