java的gc日志在哪看widows jvm开启gc日志

转载

IT剑客风云 2023-10-20 17:50:13

文章标签 java的gc日志在哪看widows jvm java sed 老年代 文章分类 Java 后端开发

JVM调优之GC日志分析及可视化工具介绍

文章目录

JVM调优之GC日志分析及可视化工具介绍

GC日志参数

GC日志参数
常用垃圾收集器参数

GC日志分析

日志的含义
使用 ParNew + Serial Old 的组合进行内存回收
使用 Parallel Scavenge + Parallel Old 的组合进行内存回收
大对象回收分析

日志分析工具

日志工具简介
测试准备
GCeasy
GCViewer

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

GC日志参数

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

GC日志参数

参数	说明
-XX:+PrintGC	打印简单GC日志。类似：-verbose:gc
-XX:+PrintGCDetails	打印GC详细信息
-XX:+PrintGCTimeStamps	输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps	输出GC的时间戳（以日期的形式）
-XX:+PrintHeapAtGC	在进行GC的前后打印出堆的信息
-Xloggc:…/logs/gc.log	指定输出路径收集日志到日志文件

例如，使用如下参数启动：

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

常用垃圾收集器参数

参数	描述
UseSerialGC	虚拟机在运行在 Client 模式下的默认值，打开此开关后，使用 Serial+Serial Old 收集器组合进行内存回收
UseParNewGC	使用 ParNew + Serial Old 收集器组合进行内存回收
UseConcMarkSweepGC	使用 ParNew + CMS + Serial Old 的收集器组合尽心内存回收，当 CMS 出现 Concurrent Mode Failure 失败后会使用 Serial Old 作为备用收集器
UseParallelOldGC	使用 Parallel Scavenge + Parallel Old 的收集器组合
UseParallelGC	使用 Parallel Scavenge + Serial Old （PS MarkSweep）的收集器组合
SurvivorRatio	新生代中 Eden 和任何一个 Survivor 区域的容量比值，默认为 8
PretenureSizeThreshold	直接晋升到老年代对象的大小，单位是Byte
UseAdaptiveSizePolicy	动态调整 Java 堆中各区域的大小以及进入老年代的年龄
ParallelGCThreads	设置并行 GC 时进行内存回收的线程数
GCTimeRatio	GC 时间占总时间的比率，默认值为99，只在 Parallel Scavenge 收集器的时候生效
MaxGCPauseMillis	设置 GC 最大的停顿时间，只在 Parallel Scavenge 收集器的时候生效
CMSInitiatingOccupancyFraction	设置 CMS 收集器在老年代空间被使用多少后触发垃圾收集，默认是 68%，仅在 CMS 收集器上生效
CMSFullGCsBeforeCompaction	设置 CMS 收集器在进行多少次垃圾回收之后启动一次内存碎片整理
UseG1GC	使用 G1 (Garbage First) 垃圾收集器
MaxGCPauseMillis	设置最大GC停顿时间(GC pause time)指标(target). 这是一个软性指标(sox goal), JVM 会尽量去达成这个目标.
G1HeapRegionSize	使用G1时Java堆会被分为大小统一的的区(region)。此参数可以指定每个 heap区的大小. 默认值将根据 heap size 算出最优解. 最小值为 1Mb, 最大值为 32Mb

GC日志分析

日志的含义

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

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

[GC (Allocation Failure) [PSYoungGen: 6146K->904K(9216K)] 6146K->5008K(19456K), 0.0038730secs] [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]; //出现一次 Minor GC
	}
}

打印结果

[GC (Allocation Failure) [ParNew: 8021K->647K(9216K), 0.0032114 secs] 8021K->6791K(19456K), 0.0032618 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 9216K, used 4910K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  52% used [0x00000000fec00000, 0x00000000ff029858, 0x00000000ff400000)
  from space 1024K,  63% used [0x00000000ff500000, 0x00000000ff5a1fc0, 0x00000000ff600000)
  to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
 tenured generation   total 10240K, used 6144K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
   the space 10240K,  60% used [0x00000000ff600000, 0x00000000ffc00030, 0x00000000ffc00200, 0x0000000100000000)
 Metaspace       used 3303K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 359K, capacity 388K, committed 512K, reserved 1048576K

结果分析

首先我们通过JVM参数-Xms20M、-Xmx20M、-Xmn10M 把Java堆大小设置为20MB，不可扩展。其中10M分配给新生代，另外10M分配给老生代。

java的gc日志在哪看widows jvm开启gc日志_jvm

通过上面的GC日志我们可以看出一开始出现了一次，因为没有写明时FullGC，说明这次GC是一次Young GC(MinorGC)。 引起GC的原因是内存分配失败，因为分配allocation的时候，Eden区已经没有足够的区域来分配了，所以发生来本次 MinorGC 。经过 MinorGC 之后，由ParNew后面的参数可知，新生代的已使用容量从8021->647（总容量是9216K，我们设置的10M，实际运行时会比设置的效小一点）。

8021K->6791K(19456K)表示的是整个堆空间大小的变化，GC后堆空间大小由原先的8021K，减为6791K，19456K是堆的总大小（仍然比我们设置的20M要小一点）。

可以看到整个堆的内存总量却几乎没有减少，原因就是，由于我们设置的年轻代大小为10M，由8：1：1的比例划分Eden，S0，S1区域大小可知，Eden大小为8M，S0大小为1M，S1大小为1M。当创建allocation1~3字节数组后，Eden区大小已经使用了6M，不够存放字节数组allocation4。

此时就会进行一次Young GC(Minor GC)，由于发现新生代没有可以回收的对象，且剩余内存不足以存储allocation4。所以不得不使用内存担保将allocation1～3 三个对象提前转移到老年代。此时再在 Eden 区域为 allocation 分配 4MB 的空间，因此最后我们发现 Eden 区域占用了 4MB（used 4910K），老年代占用6MB（used 6144K）。

什么是内存担保

在JVM的内存分配时，内存分配担保机制就是当在新生代无法分配内存的时候，把新生代的对象转移到老生代，然后把新对象放入腾空的新生代。

这个担保机制，是在jdk6才默认开启的，参数为【-XX:+HandlePromotionFailure】，现在用的最多的版本都是jdk8，所以这个参数可以忽略。参数HandlePromotionFailure的含义就是，是否允许担保失败，因为这里涉及到一个概率问题，也就是担保的核心判断条件：老年代最大的连续空间，是否大于历次晋升到老年代的对象的平均大小。

如果大于，就说明老年代很可能能够装载这次的新生代晋升对象，这时候不需要执行Full GC，冒险执行一次Youth GC，然后将新生代中存活的对象晋升到老年代。如果没有这个担保机制，就会直接执行Full GC，这样对性能的影响频次会增加。当然，如果小于，就说明这次担保很可能失败，需要执行Full GC。所以担保机制，是为了减少Full GC的执行频次，提高了应用的性能。

使用 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参数：
     * 1. -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) [ParNew: 6146K->872K(9216K), 0.0032114 secs] 6146K->4976K(19456K), 0.0032618 secs] [Times: user=0.00 sys=0.00, real=0.00 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 2041K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
  eden space 8192K,  24% used [0x00000000fec00000, 0x00000000fedfe5d8, 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 3302K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 359K, 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;
	/**
	* -Xms100M -Xmx100M -XX:SurvivorRatio=8 -XX:+PrintGCDetails -Xloggc:E://gc.log
	*/
	public static void main(String[] args) {
		ArrayList<byte[]> list = new ArrayList<byte[]>();
		for (int i = 0; i < 500; i++) {
			byte[] arr = new byte[1024 * 100];
			list.add(arr);
			try {
				Thread.sleep(20);
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
		}
	}
}

在E://gc.log生成日志如下：

Java HotSpot(TM) 64-Bit Server VM (25.281-b09) for windows-amd64 JRE (1.8.0_281-b09), built on Dec  9 2020 13:54:07 by "" with MS VC++ 15.9 (VS2017)
Memory: 4k page, physical 24941088k(11627804k free), swap 29921824k(11624816k 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 
7.369: [GC (Allocation Failure) [PSYoungGen: 27575K->3048K(30720K)] 27575K->25159K(99328K), 0.0213202 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
Heap
 PSYoungGen      total 30720K, used 29262K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 27648K, 94% used [0x00000000fdf00000,0x00000000ff899790,0x00000000ffa00000)
  from space 3072K, 99% used [0x00000000ffa00000,0x00000000ffcfa1a0,0x00000000ffd00000)
  to   space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
 ParOldGen       total 68608K, used 22111K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 32% used [0x00000000f9c00000,0x00000000fb197d90,0x00000000fdf00000)
 Metaspace       used 3805K, capacity 4536K, committed 4864K, reserved 1056768K
  class space    used 420K, capacity 428K, committed 512K, reserved 1048576K

GCeasy

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

把上篇博客生成的日志文件，上传分析，就会接到可视化界面

java的gc日志在哪看widows jvm开启gc日志_java的gc日志在哪看widows_02

jvm堆

Allocated：各部分分配大小

Peak：峰值内存使用量

关键绩效指标

java的gc日志在哪看widows jvm开启gc日志_老年代_04

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

平均GC停顿时间

最大GC停顿时间

GC停顿持续时间范围：时间范围、GC数量、百分百

交互式图表

java的gc日志在哪看widows jvm开启gc日志_老年代_05

左边菜单有很多：

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

java的gc日志在哪看widows jvm开启gc日志_java_06

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

CViewer

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

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

使用简介：

java -jar gcviewer-1.37-SNAPSHOT.jar

java的gc日志在哪看widows jvm开启gc日志_java的gc日志在哪看widows_07

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。

上一篇：测绘Python 测绘专业

下一篇：java steam合计 decimal java的steam

提问和评论都可以，用心的回复会被更多人看到评论

发布评论

相关文章

官方博客	全部文章	热门标签	班级博客
了解我们	网站地图	意见反馈

鸿蒙开发者社区	51CTO学堂
51CTO	软考资讯