聊聊如何打印GC日志排查的问题

编辑: admin 分类: java 发布时间: 2021-12-03 来源:互联网
目录
  • 如何打印GC日志排查问题
    • 先来看个示例
    • 那么上面打印出来的日志，具体是什么意思呢？
    • 小结一下
  • gc日志打印时间戳

    如何打印GC日志排查问题

    在工作当中，有时候我们会需要打印GC的相关信息来定位问题。该如何做呢？

    先来看个示例

    public static void main(String[] args) {
        List<Integer> list0 = new ArrayList<>();
        long start0 = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            list0.add(i);
        }
        System.out.println("cost: " + (System.currentTimeMillis() - start0));

        List<Integer> list1 = new ArrayList<>();
        long start1 = System.currentTimeMillis();
        for (int i = 0; i < 1000000; i++) {
            list1.add(i);
        }
        System.out.println("cost: " + (System.currentTimeMillis() - start1));
    }

    直接运行，结果如下

    cost: 135

    cost: 85

    你应该觉得奇怪，同样的往一个list插入100万条数据，为啥第一个耗时比较久？

    这种时候，有经验的工程师应该能马上怀疑是GC的问题，我们可以通过在运行时添加JVM参数来打印程序运行时的GC情况。

    -XX:+PrintGCDetails

    如果是使用IDEA来运行，可以在 run configurations 的 VM options添加上面的参数即可。

    再次运行，输出如下

    [GC (Allocation Failure) [PSYoungGen: 1536K->512K(1536K)] 1884K->1234K(262144K), 0.0009030 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
    [GC (Allocation Failure) [PSYoungGen: 1302K->1017K(2560K)] 2025K->1948K(263168K), 0.0012290 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
    [GC (Allocation Failure) [PSYoungGen: 2553K->1504K(3072K)] 3484K->3051K(263680K), 0.0017210 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    [GC (Allocation Failure) [PSYoungGen: 3040K->2033K(4608K)] 4587K->4228K(265216K), 0.0023170 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
    [GC (Allocation Failure) [PSYoungGen: 4593K->2560K(5120K)] 8195K->6681K(265728K), 0.0249700 secs] [Times: user=0.31 sys=0.00, real=0.03 secs]
    [GC (Allocation Failure) [PSYoungGen: 5120K->3584K(6656K)] 11352K->11408K(267264K), 0.0241680 secs] [Times: user=0.30 sys=0.01, real=0.03 secs]
    [GC (Allocation Failure) [PSYoungGen: 6656K->3296K(7680K)] 17645K->17909K(268288K), 0.0349010 secs] [Times: user=0.45 sys=0.00, real=0.03 secs]
    [GC (Allocation Failure) [PSYoungGen: 6368K->3328K(10240K)] 25729K->25825K(270848K), 0.0314260 secs] [Times: user=0.40 sys=0.00, real=0.03 secs]
    cost: 137
    [GC (Allocation Failure) [PSYoungGen: 8166K->4469K(10240K)] 30663K->30103K(270848K), 0.0285370 secs] [Times: user=0.36 sys=0.01, real=0.03 secs]
    [GC (Allocation Failure) [PSYoungGen: 9166K->3785K(13312K)] 34800K->33427K(273920K), 0.0226780 secs] [Times: user=0.28 sys=0.01, real=0.02 secs]
    [GC (Allocation Failure) [PSYoungGen: 11465K->6142K(13824K)] 41107K->38511K(274432K), 0.0065540 secs] [Times: user=0.08 sys=0.00, real=0.00 secs]
    [GC (Allocation Failure) [PSYoungGen: 13822K->7837K(19456K)] 46191K->44246K(280064K), 0.0099720 secs] [Times: user=0.11 sys=0.01, real=0.01 secs]
    cost: 79

    所以你大概明白了，第一次minor gc的次数比第二次多，所以运行时间比较长。

    那么上面打印出来的日志，具体是什么意思呢？

    已经有人画出了很详细的图，我借来用下

    在这里插入图片描述

    在这里插入图片描述

    如果想了解 GC 的更多的内容，可以看看 oracle 官方对于 HosSpotJVM GC的详细介绍

    小结一下

    了解GC日志的打印方法，并且能看懂GC日志，对于查找定位问题非常有帮助的。

    我自己就遇到过生产上一个CPU飙到好几百的情况，打印GC日志发现 JVM 一直在 fullGC，而且每次GC之后内存基本没有变化，从而定位到应用程序可能存在内存泄漏的问题。

    gc日志打印时间戳

    今天发现在jvm参数中，用-XX:+PrintGCDateStamps 替换 -XX:PrintGCTimeStamps，就可以打印真实的gc时间信息，而不像现在相对启动时间的秒数。

    有了真实时间戳，可以方便与应用的log做对比，便于分析排查问题。

    线下实验过，真实有效gc日志打印时间戳

    以上为个人经验，希望能给大家一个参考，也希望大家多多支持自由互联。

    【原URL http://www.yidunidc.com/mggfzq.html 请说明出处】
    更多阅读