3分钟带你看懂 GC 日志!
01、背景介绍
在之前的几篇文章中,我们介绍了 JVM 内部布局、对象的创建过程、运行期的相关优化手段、垃圾对象的回收算法以及垃圾收集器等相关知识。
那么如何分析当前虚拟机性能呢?其中 GC 日志起到至关重要的作用。
实际上,每种垃圾收集器都有它独立的日志格式,尽管如此,虚拟机为了方便用户阅读,将各个收集器的日志都维持在一定的共性状态。
下面我们一起来看看不同的垃圾收集器,相关的 GC 日志内容。
本文是基于 JDK 1.8 版本运行,可能不同的版本各个内存区域的名称略有不同,对知识的理解不会产生明显的误区。
02、触发GC时机
通常,GC 触发的条件有两种:
1.程序调用 System.gc
时可能会触发,此时会建议 JVM 进行垃圾回收,但不代表一定会进行 GC 动作;2.系统自身来决定 GC 触发的时机,比如年轻代空间不足、老年代空间不足等就会主动触发 GC 动作
以上两种行为都会产生 GC 日志。
03、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]
Heap
def 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 1056768K
class 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]
Heap
par 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 1056768K
class 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]
Heap
PSYoungGen 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 1056768K
class 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]
Heap
par 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 1056768K
class 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]
Heap
garbage-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 1056768K
class space used 336K, capacity 388K, committed 512K, reserved 1048576K
G1 收集器与以上收集器都不同,它会把整个 Java 堆分成若干个大小相等的独立区域,也是日志中的 Region,然后针对优先级高的 Region 区域进行收集。Region 区域可能存放的是年轻代的对象,也可能是老年代的对象。
04、小结
以上的日志输出,会发现很多的共性。
比如,以“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 日志,进行了一次知识内容的整合和总结,内容比较多,如果有描述不对的地方,欢迎大家留言指出,不胜感激。
写到最后
最后感谢各位的阅读,原创不易,如果觉得文章写的不错,欢迎大家转发,点击【在看】让更多的人看到,谢谢大家的支持!