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中的描述。

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