JVM如何读GC日志以及如何使用工具分析

      GC 垃圾回收必须要保证一直性的快照中进行， 一直性的意思是指分析工作期间整个系统就像静止在一个时间点上， 不能在分析过程中对象关系还在发生变化，所以GC分析过程中必须要让JAVA程序停顿，Sun把这个事件称之为STW (Stop the World) , 打个比方， 《深入理解Java虚拟机》里作者举了一个例子， 我觉得十分恰当： 当你要打扫孩子的屋子时，你会让孩子做在椅子上不动，然后才能顺利的完成打扫房间。如果你一边打扫房间，孩子一边在房间里仍东西，你将永远无法完成打扫房间的工作

      GC 垃圾回收时候会让JAVA程序停顿，从GC回收器的发展来看， GC算法的设计时候考虑最多的也就是如何减少这个停顿时间。当停顿时间越少其实系统的性能也就越好。 当停顿的次数或者时间越长，那么系统的性能也就越差。 因此对系统而言， 当系统性能变慢的时候，分析GC日志来确认问题点也就变得越来越重要了，我曾经遇到过一个问题，售后反馈说系统变得突然慢，性能很差，体验非常不好。 这个问题的原因就是虚拟机在频繁Full GC，FULL GC 就会产生Stop the world, 那么整个问题就变成了为什么系统会频繁Full GC 这里不再多说，因为这是另一个故事了

下面的示例说明如何打印、保存、查看GC日志

配置JVM参数打印GC日志

Run–>Edit Configuration–>VM options: -XX:+PrintGCDetails -verbose:gc -Xloggc:d:/gc.log

• -XX:+PrintGCDetails 表示打印出GC的详细信息
• -verbose:gc 表示开启gc日志
• -Xloggc:d:/gc.log 表示日志的存放位置

这里用的IDE是Intellij IDEA , 如果是Eclips可以在

Run–>Run/Debug Configuration–> Arguments -> VMargument中修改参数

 

测试代码源码，这个代码还是使用前面分析finalize方法的例子

public class FinalizeEscapeGC {
    public static FinalizeEscapeGC SAVE_HOOK = null;

    public void isAlive() {
        System.out.println("yes,i am still alive：)");
    }

    @
            Override
    protected void finalize() throws Throwable {
        super.finalize();
        System.out.println("finalize mehtod executed！");
        FinalizeEscapeGC.SAVE_HOOK = this;
    }

    public static void main(String[] args) throws Throwable {
        SAVE_HOOK = new FinalizeEscapeGC();
        //对象第一次成功拯救自己
        SAVE_HOOK = null;
        System.gc();
        //因为finalize方法优先级很低，所以暂停0.5秒以等待它
        System.out.println("sleep 500");
        Thread.sleep(500);
        System.out.println("after sleep 500");
        if (SAVE_HOOK != null) {
            SAVE_HOOK.isAlive();
        } else {
            System.out.println("no,i am dead：(");
        }
        //下面这段代码与上面的完全相同，但是这次自救却失败了
        SAVE_HOOK = null;
        System.gc();
        //因为finalize方法优先级很低，所以暂停0.5秒以等待它
        Thread.sleep(500);
        if (SAVE_HOOK != null) {
            SAVE_HOOK.isAlive();
        } else {
            System.out.println("no,i am dead：(");
        }
    }

}

执行后-Xloggc 配置的地址下会生成对应的日志， 截取部分日志信息

[1.097s][info][gc,phases      ] GC(1) Phase 1: Mark live objects 2.649ms
[1.097s][info][gc,phases,start] GC(1) Phase 2: Prepare for compaction
[1.097s][info][gc,phases      ] GC(1) Phase 2: Prepare for compaction 0.377ms
[1.097s][info][gc,phases,start] GC(1) Phase 3: Adjust pointers
[1.098s][info][gc,phases      ] GC(1) Phase 3: Adjust pointers 0.832ms
[1.098s][info][gc,phases,start] GC(1) Phase 4: Compact heap
[1.099s][info][gc,phases      ] GC(1) Phase 4: Compact heap 0.675ms
[1.099s][info][gc,heap        ] GC(1) Eden regions: 1->0(3)
[1.099s][info][gc,heap        ] GC(1) Survivor regions: 0->0(0)
[1.099s][info][gc,heap        ] GC(1) Old regions: 4->1
[1.099s][info][gc,heap        ] GC(1) Humongous regions: 0->0
[1.099s][info][gc,metaspace   ] GC(1) Metaspace: 6279K->6279K(1056768K)
[1.099s][info][gc             ] GC(1) Pause Full (System.gc()) 1M->0M(8M) 5.159ms
[1.099s][info][gc,cpu         ] GC(1) User=0.00s Sys=0.00s Real=0.00s
[1.600s][info][gc,heap,exit   ] Heap
[1.600s][info][gc,heap,exit   ]  garbage-first heap   total 8192K, used 984K [0x0000000681600000, 0x0000000800000000)
[1.600s][info][gc,heap,exit   ]   region size 1024K, 1 young (1024K), 0 survivors (0K)
[1.600s][info][gc,heap,exit   ]  Metaspace       used 6294K, capacity 6475K, committed 6528K, reserved 1056768K
[1.600s][info][gc,heap,exit   ]   class space    used 548K, capacity 606K, committed 640K, reserved 1048576K

 

日志描述说明：

• [0.702s] 表示处理使用时间
• [info ] 日志等级
• GC(1) Eden regions 表示GC发生的位置
• 3M->0M(14M) 表示GC当前状况 ： 已经使用内存量 -> GC后内存状况 （该内存区域总容量）
• 3.742ms ：最后1个时间表示该区域GC占用的时间
• User=0.00s Sys=0.00s Real=0.00s：这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间（Wall Clock Time）

      GC垃圾收集日志可以帮助我们优化垃圾收集暂停时间，提高整体应用程序的响应时间，预测生产中断，降低计算成本,但是通过GC日志排查问题点会有一种大海捞针的感觉。但我们可以通过一些工具来帮助我们分析GC日志，比如gceasy，使用方式也很简单

首先访问 Universal JVM GC analyzer - Java Garbage collection log analysis made easy   （地址

https://gceasy.io/）通过页面选择要分析的GC日志，示意图如下

点击分析后就可以查看GC分析报告，示意图如下

 

  

上一篇：JVM虚拟机垃圾回收中的finalize方法作用https://blog.csdn.net/Beijing_L/article/details/120185907