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分配给老生代。
通过上面的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/
把上篇博客生成的日志文件，上传分析，就会接到可视化界面
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日志，可以看到如下图，图标是可以放大缩小的，主要内容就是红线圈住的部分，里面的内容跟上面的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
打开之后，点击File->Open File打开我们的GC日志，可以看到如下图，图标是可以放大缩小的，主要内容就是红线圈住的部分，里面的内容跟上面的GCeasy的比较类似，具体的可以看下GitHub中的描述。
