Java虚拟机系列(四)---查看GC日志

时间:2022-11-16 21:10:29

这一节穿插一点如何在eclipse中配置并查看某个Java应用GC日志的知识点,我也是通过调研知道的,因为书中写的不是很详细,主要是为下一节做准备。

一、eclipse中配置GC

在eclipse中如果要给某个应用配置GC日志,首先右击该应用(main方法所在的类)->Run As->Run Configurations->Arguments,在VM arguments中配置如下参数:

-Xms20m //最小堆内存
-Xmx20m //最大堆内存
-XX:+PrintGCTimeStamps  //打印GC时间
-XX:+PrintGCDetails      //打印GC的详细信息
-verbose:gc //开启GC日志
-Xloggc:d:/gc4.log  //GC日志存放的位置,后面就是查看这个日志文件
-Xmn10M  //新生代内存区域的位置
-XX:SurvivorRatio=8  //在复制算法中Eden区和Survivor区的比例(后续章节会细说)

如下图所示:

Java虚拟机系列(四)---查看GC日志

配置完成之后点击Applay->Run,等程序运行完之后可以到刚才配置的日志路径中,找到相应的文件进行查看。

二、查看GC

下面以一个具体的实例来查看并分析一下GC日志

1、创建三个互相引用的对象实例

Java虚拟机系列(四)---查看GC日志

2、配置GC

Java虚拟机系列(四)---查看GC日志

3、查看日志内容

Java HotSpot(TM) 64-Bit Server VM (25.121-b13) for windows-amd64 JRE (1.8.0_121-b13), built on Dec 12 2016 18:21:36 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 4057600k(480696k free), swap 8113324k(3128576k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
0.121: [GC (System.gc()) [PSYoungGen: 4219K->680K(9216K)] 4219K->3760K(19456K), 0.0024028 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.124: [Full GC (System.gc()) [PSYoungGen: 680K->0K(9216K)] [ParOldGen: 3080K->3639K(10240K)] 3760K->3639K(19456K), [Metaspace: 2587K->2587K(1056768K)], 0.0062622 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
Heap
PSYoungGen total 9216K, used 82K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
eden space 8192K, 1% used [0x00000000ff600000,0x00000000ff614920,0x00000000ffe00000)
from space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
to space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
ParOldGen total 10240K, used 3639K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
object space 10240K, 35% used [0x00000000fec00000,0x00000000fef8de58,0x00000000ff600000)
Metaspace used 2593K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 286K, capacity 386K, committed 512K, reserved 1048576K

上面的就是生成的GC日志,其中:

前两行是虚拟机的一些信息,如使用的是HotSpot虚拟机,JRE版本等;第三行是刚才配置的参数信息,真正的GC信息是第4、5行,所以这里直接将4、5两行单独拿出来进行分析:

0.121: [GC (System.gc()) [PSYoungGen: 4219K->680K(9216K)] 4219K->3760K(19456K), 0.0024028 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.124: [Full GC (System.gc()) [PSYoungGen: 680K->0K(9216K)] [ParOldGen: 3080K->3639K(10240K)] 3760K->3639K(19456K), [Metaspace: 2587K->2587K(1056768K)], 0.0062622 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

1)最前面的数字0.121、0.124代表了GC发生的时间,这个数字的含义是从JAVA虚拟机启动以来经过的秒数;

2)GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型,而不是用来区分新生代GC还是老年代GC。如果有"Full",说明这次GC是发生了Stop-The-World的,就是指在执行GC操作的时候,会停止掉当前正在进行的其他线程,有一种“这是我的地盘,你们都给我让开”的霸道有木有?如果是调用System.gc()的方法所触发的收集,将会显示“Full GC(System.gc)",本文的例子就是使用System.gc()进行的收集;

3)接下来的"[PSYoungGen"、“[ParOldGen”、“[Metaspace“标示GC发生的区域,这里显示的区域名称与所使用的GC收集器密切相关(以后会对垃圾收集器进行详细介绍),下面是常见收集器所代表的的区域名称:

1>如果使用的是Serial(串行)收集器,新生代名为Default New Generation ,显示就是DefNew

2>如果使用的是ParNew(并行)收集器,新生代名称就会变为[Parnew,意思为Parallel New Generation

3>如果采用的是Parallel Scavenge收集器,新生代名称为PSYongGen

老年代和永久代同理,名称由垃圾收集器决定

如上面的日志中新生代名称为[PSYoungGen,使用的是Parallel Scavenge收集器;老年代名称为[ParOldGen,使用的是Paralled Old收集器(Parallel Scavenge收集器的老年代版本),还有元空间区域,有些文章中使用的是”[PermGen“,这时jdk8之前的版本,由于我使用的是jdk8,所以已经被”[Metaspace“所代替,至于为什么被代替,可以参考篇文章:https://blog.csdn.net/zhushuai1221/article/details/52122880

4)每个区域冒号后面,中括号内部的”680K->0K(9216K)]“含义是”GC前该内存区域已使用容量->GC后该内存区域已使用容量(该内存区域总容量)“。而在方括号之外的”3760K->3639K(19456K)“表示的是"GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量)"

5)再往后 0.0062622 secs表示该内存区域GC所占用的时间单位是秒,有的收集器会给出具体的时间,如本例中的”[Times: user=0.06 sys=0.00, real=0.01 secs]“,这里面的user、sys、real与Linux命令所输出的时间含义一直,分别代表用户态消耗的CPU时间、内核态消耗的CPU时间和操作从开始到结束所经过的墙钟时间(Wall Clock Time)

TIPS:墙钟时间与CPU时间的区别是,墙钟时间包括各种非运算的等待耗时,例如等待磁盘的IO、等待线程阻塞;而CPU时间不包括这些耗时,但当系统中有对CPU或者多核的话,多线程操作会叠加这些CPU时间,所以读者看到user或sys的时间超过real时间是完全正常的。

上面对GC日志中各从参数的介绍摘自《深入理解Java虚拟机(第二版)》

再往下看,从第6行开始到结束的内容是各内存区域容量的变化情况!

备注:以上内容来源于《深入理解Java虚拟机》,根据自己的理解来总结,有些内容和书本内容相同是因为只有这么描述才比较好懂,毕竟大神还是大神,是颜色不一样的烟火!!