JVM系列(十一) -GC日志分析

最近对 JVM 技术知识进行了重新整理，再次献上 JVM系列文章合集索引，感兴趣的小伙伴可以直接点击如下地址快速阅读。

• JVM系列(一) -什么是虚拟机
• JVM系列(二) -类的加载过程
• JVM系列(三) -内存布局详解
• JVM系列(四) -对象的创建过程
• JVM系列(五) -对象的内存分配流程
• JVM系列(六) -运行期优化技术
• JVM系列(七) -垃圾收集算法
• JVM系列(八) -垃圾收集器
• JVM系列(九) -GC日志分析
• JVM系列(十) -常用调优命令汇总
• JVM系列(十一) -常用调优工具介绍
• JVM系列(十二) -常用调优参数总结

一、背景介绍

在之前的文章中，我们介绍了 JVM 的垃圾收集器相关知识，那么如何分析当前虚拟机性能呢？其中 GC 日志起到至关重要的作用。

实际上，每种垃圾收集器都有它独立的日志格式，尽管如此，虚拟机为了方便用户阅读，将各个收集器的日志都维持在一定的共性状态。

下面我们一起来看看不同的垃圾收集器，相关的 GC 日志内容。

本文是基于 JDK 1.8 版本运行，可能不同的版本各个内存区域的名称略有不同，对知识的理解不会产生明显的误区。

二、触发GC时机

通常，GC 触发的条件有两种：

• 1.程序调用System.gc时可能会触发，此时会建议 JVM 进行垃圾回收，但不代表一定会进行 GC 动作；
• 2.系统自身来决定 GC 触发的时机，比如年轻代空间不足、老年代空间不足等就会主动触发 GC 动作

以上两种行为都会产生 GC 日志。

三、GC日志

在介绍之前，我们先看一段代码，下文的 GC 日志都会基于这段代码来分析。

/*** 虚拟机参数：-verbose:gc*/
public class GCObjectTest {public Object instance = null;/*** 设置成员属性占用一点内存，2M*/public byte[] bigSize = new byte[2 * 1024 * 1024];public static void main(String[] args) {GCObjectTest objectA = new GCObjectTest();GCObjectTest objectB = new GCObjectTest();// 设置两个对象互相引用objectA.instance = objectB;objectB.instance = objectA;objectB = null;objectA = null;// 触发 GC,不一定实时生效System.gc();}
}

运行时加上-verbose:gc参数，以便简要的查看程序的 GC 情况，运行后的输出结果如下！

[GC (System.gc())  6101K->520K(125952K), 0.0022878 secs]
[Full GC (System.gc())  520K->408K(125952K), 0.0049120 secs]

以上代码是一段对象相互引用的场景，但是 JVM 还是将对象回收了，也应证了一点，HotSpot 虚拟机并不是通过引用计数法来判定对象是否存活的。

下面我们还是以上面的代码为例，设置不同的虚拟机参数，看看 GC 日志情况。

3.1、Serial 和 Serial Old 组合垃圾收集器

Serial 和 Serial Old 组合的垃圾收集器，可以在运行时设置如下参数来开启。

-XX:+PrintGCDetails
-XX:+UseSerialGC

运行之后，输出结果如下！

[Full GC (System.gc()) [Tenured: 0K->393K(87424K), 0.0104804 secs] 6891K->393K(126720K), [Metaspace: 3052K->3052K(1056768K)], 0.0105689 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heapdef new generation   total 39424K, used 351K [0x0000000740000000, 0x0000000742ac0000, 0x000000076aaa0000)eden space 35072K,   1% used [0x0000000740000000, 0x0000000740057c58, 0x0000000742240000)from space 4352K,   0% used [0x0000000742240000, 0x0000000742240000, 0x0000000742680000)to   space 4352K,   0% used [0x0000000742680000, 0x0000000742680000, 0x0000000742ac0000)tenured generation   total 87424K, used 393K [0x000000076aaa0000, 0x0000000770000000, 0x00000007c0000000)the space 87424K,   0% used [0x000000076aaa0000, 0x000000076ab02608, 0x000000076ab02800, 0x0000000770000000)Metaspace       used 3062K, capacity 4496K, committed 4864K, reserved 1056768Kclass space    used 336K, capacity 388K, committed 512K, reserved 1048576K

各个参数描述介绍：

• def new generation：表示年轻代的内存使用情况，其中eden space表示Eden空间的内存使用情况；from space表示From Survivor空间的内存使用情况；to space表示To Survivor空间的内存使用情况；
• tenured generation：表示老年代的内存使用情况
• Metaspace：表示元空间的内存使用情况，在 JDK1.7 中称为永久代

3.2、ParNew 和 Serial Old 组合垃圾收集器

ParNew 和 Serial Old 组合的垃圾收集器，可以在运行时设置如下参数来开启。

-XX:+PrintGCDetails
-XX:+UseParNewGC

运行之后，输出结果如下！

[Full GC (System.gc()) [Tenured: 0K->395K(87424K), 0.0044216 secs] 6891K->395K(126720K), [Metaspace: 3058K->3058K(1056768K)], 0.0044869 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
Heappar new generation   total 39424K, used 1052K [0x0000000740000000, 0x0000000742ac0000, 0x000000076aaa0000)eden space 35072K,   3% used [0x0000000740000000, 0x0000000740107228, 0x0000000742240000)from space 4352K,   0% used [0x0000000742240000, 0x0000000742240000, 0x0000000742680000)to   space 4352K,   0% used [0x0000000742680000, 0x0000000742680000, 0x0000000742ac0000)tenured generation   total 87424K, used 395K [0x000000076aaa0000, 0x0000000770000000, 0x00000007c0000000)the space 87424K,   0% used [0x000000076aaa0000, 0x000000076ab02d70, 0x000000076ab02e00, 0x0000000770000000)Metaspace       used 3064K, capacity 4496K, committed 4864K, reserved 1056768Kclass space    used 336K, capacity 388K, committed 512K, reserved 1048576K

其中par new generation表示年轻代的内存使用情况，其它表达的内容与上相同。

3.3、Parallel Scavenge 和 Parallel Old 组合垃圾收集器

Parallel Scavenge 和 Parallel Old 组合的垃圾收集器，可以在运行时设置如下参数来开启。

-XX:+PrintGCDetails
-XX:+UseParallelOldGC

需要注意的是，在 jdk1.8 及之后的版本中，-XX:+UseParallelGC和-XX:+UseParallelOldGC参数效果是一样的，都是用的 Parallel Old 作为老年代收集器；而在 jdk1.7 及之后的版本中，-XX:+UseParallelGC参数用的是 Serial Old 作为老年代收集器。

运行之后，输出结果如下！

[GC (System.gc()) [PSYoungGen: 6767K->496K(38400K)] 6767K->504K(125952K), 0.0014375 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (System.gc()) [PSYoungGen: 496K->0K(38400K)] [ParOldGen: 8K->390K(87552K)] 504K->390K(125952K), [Metaspace: 3008K->3008K(1056768K)], 0.0045268 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
HeapPSYoungGen      total 38400K, used 998K [0x0000000795580000, 0x0000000798000000, 0x00000007c0000000)eden space 33280K, 3% used [0x0000000795580000,0x0000000795679b20,0x0000000797600000)from space 5120K, 0% used [0x0000000797600000,0x0000000797600000,0x0000000797b00000)to   space 5120K, 0% used [0x0000000797b00000,0x0000000797b00000,0x0000000798000000)ParOldGen       total 87552K, used 390K [0x0000000740000000, 0x0000000745580000, 0x0000000795580000)object space 87552K, 0% used [0x0000000740000000,0x0000000740061b10,0x0000000745580000)Metaspace       used 3042K, capacity 4496K, committed 4864K, reserved 1056768Kclass space    used 333K, capacity 388K, committed 512K, reserved 1048576K

其中PSYoungGen表示年轻代的内存使用情况；ParOldGen表示老年代的内存使用情况，其它表达的内容与上相同。

3.4、ParNew 和 CMS + Serial Old 组合垃圾收集器

ParNew 和 CMS + Serial Old 组合的垃圾收集器，可以在运行时设置如下参数来开启。

-XX:+PrintGCDetails
-XX:+UseConcMarkSweepGC

运行之后，输出结果如下！

[Full GC (System.gc()) [CMS: 0K->388K(87424K), 0.0214068 secs] 6192K->388K(126720K), [Metaspace: 2925K->2925K(1056768K)], 0.0214982 secs] [Times: user=0.01 sys=0.01, real=0.03 secs] 
Heappar new generation   total 39424K, used 1052K [0x0000000740000000, 0x0000000742ac0000, 0x0000000754cc0000)eden space 35072K,   3% used [0x0000000740000000, 0x0000000740107280, 0x0000000742240000)from space 4352K,   0% used [0x0000000742240000, 0x0000000742240000, 0x0000000742680000)to   space 4352K,   0% used [0x0000000742680000, 0x0000000742680000, 0x0000000742ac0000)concurrent mark-sweep generation total 87424K, used 388K [0x0000000754cc0000, 0x000000075a220000, 0x00000007c0000000)Metaspace       used 2932K, capacity 4496K, committed 4864K, reserved 1056768Kclass space    used 319K, capacity 388K, committed 512K, reserved 1048576K

其中par new generation表示年轻代的内存使用情况；concurrent mark-sweep generation表示老年代的内存使用情况，其它表达的内容与上相同。

3.5、G1 垃圾收集器

G1 垃圾收集器，可以在运行时设置如下参数来开启。

-XX:+PrintGCDetails
-XX:+UseG1GC

运行之后，输出结果如下！

[Full GC (System.gc())  5985K->395K(8192K), 0.0083534 secs][Eden: 2048.0K(14.0M)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 5985.1K(128.0M)->395.9K(8192.0K)], [Metaspace: 3059K->3059K(1056768K)][Times: user=0.01 sys=0.00, real=0.01 secs] 
Heapgarbage-first heap   total 8192K, used 395K [0x0000000740000000, 0x0000000740100040, 0x00000007c0000000)region size 1024K, 1 young (1024K), 0 survivors (0K)Metaspace       used 3066K, capacity 4496K, committed 4864K, reserved 1056768Kclass space    used 336K, capacity 388K, committed 512K, reserved 1048576K

G1 收集器与以上收集器都不同，它会把整个 Java 堆分成若干个大小相等的独立区域，也是日志中的 Region，然后针对优先级高的 Region 区域进行收集。Region 区域可能存放的是年轻代的对象，也可能是老年代的对象。

四、小结

以上的日志输出，会发现很多的共性。

比如，以“GC”开头的，通常表示年轻代的收集情况；以“Full GC”开头的，表示整个堆的收集情况，其中带有“(System.gc()) ”信息的表示调用System.gc()方法所触发的 GC。

以下面这个日志为例，来解读一下相关信息。

[Full GC (System.gc()) [PSYoungGen: 496K->0K(38400K)] [ParOldGen: 8K->390K(87552K)] 504K->390K(125952K), [Metaspace: 3008K->3008K(1056768K)], 0.0045268 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

• 1.Full GC (System.gc()表示 Full GC 类型的 GC 动作，通过调用System.gc()方法而触发；
• 2.PSYoungGen: 496K->0K(38400K)表示年轻代 GC 前使用的容量为 496K，GC 后该内存区域使用的容量为 0K，年轻代总容量为 38400K；
• 3.ParOldGen: 8K->390K(87552K)表示老年代 GC 前使用的容量为 8K，GC 后该内存区域使用的容量为 390K，老年代总容量为 87552K；
• 4.504K->390K(125952K)表示整个堆 GC 前使用的容量为 504K，GC 后该内存区域使用的容量为 390K，整个堆总容量为 125952K；
• 5.Metaspace: 3008K->3008K(1056768K)表示元空间 GC 前使用的容量为 3008K，GC 后该内存区域使用的容量为 3008K，整个元空间总容量为 1056768K；
• 6.0.0045268 secs表示 Full GC 耗时为 0.0045268 秒；
• 7.Times: user=0.01 sys=0.00, real=0.00 secs表示 Full GC 期间用户的耗时、系统的耗时、实际操作的耗时，单位秒；

Heap 后面列举的是堆的内存使用情况。

本文主要围绕 GC 日志，进行了一次知识内容的整合和总结，内容比较多，如果有描述不对的地方，欢迎大家留言指出，不胜感激。

写到最后

最后。如果感觉文章内容不错，帮忙动动小指头点个赞，点赞对我真的非常重要！加个关注我会非常感激！