GC日志分析
GC日志是一个很重要的工具,它准确记录了每一次的GC的执行时间和执行结果,通过分析GC日志可以优化堆设置和GC设置,或者改进应用程序的对象分配模式。
# 1 GC日志参数
不同的垃圾收集器,输出的日志格式各不相同,但也有一些相同的特征。熟悉各个常用垃圾收集器的GC日志,是进行JVM调优的必备一步。 解析GC日志,首先需要收集日志,常用的有以下JVM参数用来打印输出日志信息:
# 1.1 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
1.2常用垃圾收集器参数
参数 | 描述 |
---|---|
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. |
# 2 GC日志分析
# 2.1日志的含义
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)
# 2.2 使用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: 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
# 2.3 使用Parallel Scavenge+Parallel Old的组合进行内存回收
设置参数:
-Xms20M -Xmx20M -Xmn10M -XX:+UseParallelGC -XX:+PrintGCDetails -XX:SurvivorRatio=8
测试代码
package com.lagou.unit5;
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
结果分析
# 2.4 大对象回收分析
大对象直接进入老年代 虚拟机提供一个参数 -XX:PretenureSizeThreshold 用来设置直接在老年代分配的对象的大小,如果对象大于这个值就会直接在老年代分配。这样做的目的是避免在 Eden 区及两个Survivor 区之间发生大量的内存复制。
参数:
-verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:PretenureSizeThreshold=3145728
测试代码
package com.lagou.unit5;
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大小的对象直接被放到了老年代
# 3 日志分析工具
# 3.1日志工具简介
GC日志可视化分析工具GCeasy和GCviewer。通过GC日志可视化分析工具,我们可以很方便的看到JVM各个分代的内存使用情况、垃圾回收次数、垃圾回收的原因、垃圾回收占用的时间、吞吐量等,这些指标在我们进行JVM调优的时候是很有用的。
GCeasy是一款在线的GC日志分析器,可以通过GC日志分析进行内存泄露检测、GC暂停原因分析、JVM配置建
议优化等功能,而且是可以免费使用在线分析工具 https://gceasy.io/index.jsp
GCViewer是一款实用的GC日志分析软件,免费开源使用,你需要安装jdk或者java环境才可以使用。软件为GC日志分析人员提供了强大的功能支持,有利于大大提高分析效率
# 3.2测试准备
编写代码生成gc.log日志准备分析
package com.lagou.unit5;
import java.util.ArrayList;
public class TestGCLog04 {
private static final int _1MB = 1024 * 1024;
/**
* -Xms100M -Xmx100M -XX:SurvivorRatio=8 -XX:+PrintGCDetails -Xloggc:D://logs/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();
}
}
}
}
在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
# 3.3 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效率
# 3.4 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中的描述。