GC日志查看分析

0. 前言

GC(Garbage Collection)是Java虚拟机中一个很重要的组成部分，在很多情况下我们都需要查看它的日志，下面内容就是介绍如何查看GC日志。

1. GET GC日志

1.1 输出日志参数

要查看GC日志，需要设置一下jvm的参数。关于输出GC日志的参数有以下几种

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

在这里我使用PrintGCDetails这个参数。

1.2 编写演示类

接下来我先编写一个演示类，代码如下

package edu.jyu.jvm;
/**
* GC日志演示
* @author Jason
*
*/
public class GCLogDemo {

public static void main(String[] args) {
int _1m = 1024 * 1024;
byte[] data = new byte[_1m];
// 将data置为null即让它成为垃圾
data = null;
// 通知垃圾回收器回收垃圾
System.gc();
}
}

1.3 运行

好了，现在要运行这个演示类，不过在运行的时候要加上虚拟机参数PrintGCDetails，下面我分别在Eclipse和命令行中运行这个程序。

1.3.1 在Eclipse运行

先要设置一下Run Configurations



设置如下



然后点Run运行，运行后就输出了下面结果，这些就是GC日志。

[GC (System.gc()) [PSYoungGen: 3686K->664K(38400K)] 3686K->672K(125952K), 0.0016607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 664K->0K(38400K)] [ParOldGen: 8K->537K(87552K)] 672K->537K(125952K), [Metaspace: 2754K->2754K(1056768K)], 0.0059024 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen      total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to   space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen       total 87552K, used 537K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814864a0,0x0000000086980000)
Metaspace       used 2761K, capacity 4486K, committed 4864K, reserved 1056768K
class space    used 299K, capacity 386K, committed 512K, reserved 1048576K

1.3.2 在命令行运行

因为Eclipse已经把类编译好了，所以我直接进入工程目录下运行。



输出结果

[GC (System.gc()) [PSYoungGen: 3702K->784K(38400K)] 3702K->792K(125952K), 0.0014644 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 784K->0K(38400K)] [ParOldGen: 8K->648K(87552K)] 792K->648K(125952K), [Metaspace: 2763K->2763K(1056768K)], 0.0057136 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen      total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to   space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen       total 87552K, used 648K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814a2318,0x0000000086980000)
Metaspace       used 2770K, capacity 4486K, committed 4864K, reserved 1056768K
class space    used 300K, capacity 386K, committed 512K, reserved 1048576K

2. 分析日志

好了，GC日志已经得到，现在就是分析了，我把Eclipse运行后输出的GC日志放到这里来分析

[GC (System.gc()) [PSYoungGen: 3686K->664K(38400K)] 3686K->672K(125952K), 0.0016607 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System.gc()) [PSYoungGen: 664K->0K(38400K)] [ParOldGen: 8K->537K(87552K)] 672K->537K(125952K), [Metaspace: 2754K->2754K(1056768K)], 0.0059024 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
PSYoungGen      total 38400K, used 333K [0x00000000d5c00000, 0x00000000d8680000, 0x0000000100000000)
eden space 33280K, 1% used [0x00000000d5c00000,0x00000000d5c534a8,0x00000000d7c80000)
from space 5120K, 0% used [0x00000000d7c80000,0x00000000d7c80000,0x00000000d8180000)
to   space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
ParOldGen       total 87552K, used 537K [0x0000000081400000, 0x0000000086980000, 0x00000000d5c00000)
object space 87552K, 0% used [0x0000000081400000,0x00000000814864a0,0x0000000086980000)
Metaspace       used 2761K, capacity 4486K, committed 4864K, reserved 1056768K
class space    used 299K, capacity 386K, committed 512K, reserved 1048576K

GC日志开头的”[GC”和”[Full GC”说明了这次垃圾收集的停顿类型，如果有”Full”，说明这次GC发生了”Stop-The-World”。因为是调用了System.gc()方法触发的收集，所以会显示”[Full GC (System.gc())”，不然是没有后面的(System.gc())的。

“[PSYoungGen”和”[ParOldGen”是指GC发生的区域，分别代表使用Parallel Scavenge垃圾收集器的新生代和使用Parallel old垃圾收集器的老生代。为什么是这两个垃圾收集器组合呢？因为我的jvm开启的模式是Server，而Server模式的默认垃圾收集器组合便是这个，在命令行输入java -version就可以看到自己的jvm默认开启模式。还有一种是client模式，默认组合是Serial收集器和Serial Old收集器组合。

在方括号中”PSYoungGen:”后面的”3686K->664K(38400K)”代表的是”GC前该内存区域已使用的容量->GC后该内存区域已使用的容量(该内存区域总容量)”

在方括号之外的”3686K->672K(125952K)”代表的是”GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量)”

再往后的”0.0016607 sec”代表该内存区域GC所占用的时间，单位是秒。

再后面的”[Times: user=0.00 sys=0.00, real=0.00 secs]”，user代表进程在用户态消耗的CPU时间，sys代表代表进程在内核态消耗的CPU时间、real代表程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。

至于后面的”eden”代表的是Eden空间，还有”from”和”to”代表的是Survivor空间。

如果上面的内容有错误的地方或者讲的不好的地方，还请大家指点一下，我好及时修改。