如何理解GC日志？

最新推荐文章于 2023-04-29 07:37:44 发布

Shockang

最新推荐文章于 2023-04-29 07:37:44 发布

阅读量2w

点赞数 14

分类专栏： JVM 文章标签： jvm

本文链接：https://blog.csdn.net/Shockang/article/details/116905506

版权

JVM 专栏收录该内容

67 篇文章 68 订阅

订阅专栏

写在前面

本文隶属于专栏《100个问题搞定Java虚拟机》，该专栏为笔者原创，引用请注明来源，不足和错误之处请在评论区帮忙指出，谢谢！

本专栏目录结构和文献引用请见100个问题搞定Java虚拟机

解答

如何设置 GC 日志？

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2021-05-16T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

理解GC日志

为了输出 GC 日志，我们需要做些准备

Java代码

public class GCDemo {
    public static void main(String[] args) {
        int[] a;
        while(true){
            a = new int[100 * 1024 * 1024];
            a[0] = 1;
        }
    }
}

JVM配置

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs

软硬件配置参考

MacBookPro配置
JDK版本号：1.8.0_192-b12

上面的代码运行之后 GC 日志打印如下所示：

GC日志

日志分析

我们只看上图中蓝线圈中的部分：

2021-05-16T23:28:29.072-0800: 1.123: [GC (Allocation Failure) [PSYoungGen: 560K->544K(141824K)] 2458168K->2458152K(2938368K), 0.0266116 secs] [Times: user=0.24 sys=0.00, real=0.02 secs] 
2021-05-16T23:28:29.098-0800: 1.150: [Full GC (Allocation Failure) [PSYoungGen: 544K->0K(141824K)] [ParOldGen: 2457608K->432K(121344K)] 2458152K->432K(263168K), [Metaspace: 3044K->3044K(1056768K)], 0.1779021 secs] [Times: user=0.04 sys=0.16, real=0.18 secs]

最前面的数字2021-05-16T23:28:29.072-0800:代表日志打印的时间。

“1.123:”和“1.150:”代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。

GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型。

如果有“Full”，说明这次GC是发生了Stop-The-World的。如果是调用 System.gc()方法所触发的收集，那么在这里将显示“[Full GC(System)”。

Allocation Failure – 引起垃圾回收的原因. 本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的.

接下来的“[PSYoungGen:”表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的，

例如上面样例所使用的Parallel Scavenge收集器，那它配套的新生代称为“PSYoungGen”，

Serial 收集器中的新生代名为“Default New Generation"”，所以显示的是“[Defnew”。

如果是ParNew收集器，新生代名称就会变为“[ParNew”，意为“Parallel New Generation”。老年代和永久代同理，名称也是由收集器决定的。

后面方括号内部的"560K->544K(141824K)"含义是“GC前该内存区域已使用容量一>GC后该内存区域已使用容量(该内存区域总容量)”。

而在方括号之外的"2458168K->2458152K(2938368K)"表示“GC前Java堆已使用容量->GC后Java雄已使用容量(Java 堆总容量)”。

再往后，“0.0266116 secs”表示该内存区域GC所占用的时间，单位是秒。

最后的“[Times: user=0.24 sys=0.00, real=0.02 secs] ”，这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU 时间、内核态消耗的CPU事件和操作从开始到结東所经过的墙钟时间(Wall Clock Time)。