JVM系列之:日志分析工具:GCViewer、VisualVM、GCeasy

2,673

本文为《深入学习 JVM 系列》第二十四篇文章

GCViewer

GCViewer 是一个可以将 JVM 中的 gc log 可视化的工具,使用该工具可以帮助你充分的发现 JVM 垃圾回收中的潜在问题,让你可以更加准确的做出关于 JVM GC 优化的决策。

安装并启动

git clone https://github.com/chewiebug/GCViewer.git
//或者用 IDEA打开项目后,用 maven进行打包
mvn clean pacakge
//得到一个 jar包
cd target

java -jar gcviewer-1.36.jar

导出 gc log

如果是本地程序,比如还是上述 OutOfMemoryTest 文件中的代码,可以修改 JVM 参数如下:

-Xms60M -Xmx60M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/Users/xxx/Documents/logs/gc.log

如果是 SpringBoot 项目,直接使用java -jar的方式启动,那么开启 gc log 的方式非常简单。只需要在启动命令加如下参数,就可以在启动目录中找到gc.log的文件。

java  -Xloggc:gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -jar mybatis-generator-1.0-SNAPSHOT.jar

如果是传统的 Web 部署方式,放到 tomcat 里面启动,那么可以通过修改 bin/catalina.sh 这个文件来开启 gc log。

JAVA_OPTS='-Xloggc:/tmp/gc.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails'

日志分析

GCViewer 启动后,打开我们获得的 gc log 文件(这里打开是本地程序导出的 log文件),看到类似这样一个界面。

GCViewer 有两个部分,其中显示了日志分析的结果。一个是左侧的图表,另一个是右侧的数据面板。下面将解释这些部分的内容。

图表

GCViewer 在图表(第一个选项卡)中显示多条线等,可以点击 View 按钮选择显示哪些线条,具体每个曲线的地方代表什么意思官网都讲的很清楚了。

其中黑色的竖线表示 Full GC,这样的线越少越好。就像上图所示,Full GC 后老年代并没有释放多少空间,所以才会抛出 OOM 异常。

数据面板

点击 Summary,

这里只挑几个重要的参数进行介绍:

  • Max heap after full GC:Full GC 后的堆内存大小

  • Total Time:GC 总耗时

  • Accumulated Pauses:GC 过程中暂停总时长

  • Throughput(吞吐量):上图显示是 86.8%,有些系统要求吞吐量至少为 90%,那么就说明需要进行 GC 优化。

点击 Pause,

  • Accumulated Pauses:GC 过程中暂停总时长

  • Number of Pauses:暂停总次数

  • Avg Pause:平均暂停时间

  • Avg pause interval:平均暂停的间隔时间

如果你的 Full GC 平均的暂停时间很长(大于1s),或者平均暂停间隔非常的短(小于10s),说明可能你的 GC 回收是有问题的,可能需要优化。

Java VisualVM

VisualVM 是一个功能强大的多合一故障诊断和性能监控的可视化工具,它集成了多种性能统计工具的功能,使用 VisualVM 可以代替 jstat、jmap、jhat、jstack。VisualVM 可以作为独立的软件安装。

VisualVM 主页面如下所示,

要在 VisualVM 的配置文件中增加关于 JDK 的信息,否则后续关联本地执行程序对应的进程,可能出问题。

配置文件位于 /Resources/visualvm/etc 文件夹下,在 visualvm.conf 中增加如下配置:

visualvm_jdkhome="/Library/Java/JavaVirtualMachines/jdk1.8.0_301.jdk/Contents/Home"

Overview

还是继续使用上文的本地案例,执行上述程序,在 VisualVM 页面左侧双击程序对应的进程,首先进入 Overview 页面。

该页面可以查看程序的基本情况,比如进程 ID、Main class、JDK 版本、启动参数等等。

Monitor

点击页面上的 Monitor,可以监控应用程序 CPU、堆、方法区、类加载和线程数的总体情况。如下图所示:

点击“Perform GC”和“Heap Dump”按钮还可以手动执行 Full GC 和生成堆快照,比如说点击“Heap Dump”按钮,得到下述图片:

上述堆 dump 还可以通过这种方式查看,右键菜单中的 “Heap Dump“,

这里我们重点讲一下 heap dump 页面的内容,该页面又提供了5个基本功能页:summary、Objects、Threads、OQL Consle、R Console。

1、Summary 页面展示了当前内存的整体信息,包括内存大小 、实例总数、类总数等。

在上述页面还可以进行很多操作,比如点击“Classe上 by Size of Instances”下的 char[],进入详情页。

这个界面和 MAT 工具解析得到的内容很像,所以说 VisualVM 功能很强大。

我们再点击该页面上的 “GC Root”按钮,可以得到下述内容:

关于 char[] 对象的引用层次关系十分清晰。

2、Objects 页面中,显示了每个类的实例数占用空间。除此之外,还可以对比两个不同的内存快照文件,通过对比可以发现程序在运行的不同时刻,内存数据的变化,如下图所示。

如上所示,我们生成了两次内存快照,当前是在 24:50 时刻生成的,与 23:43 生成的做对比。

点击 OK 后,

可以发现在这段时间内,类对象实例个数具体增加了多少个。

3、在 Threads 页面中,可以看到线程的执行链路。

4、关于 OQL Consle、可知的是该面板是运行 OQL 查询语句的,是对 HeapDump 进行查询,类似于 SQL 的查询语言。OQL由3个部分组成:select 子句、from 子句和 where 子句。select 子句指定查询结果要显示的内容。from 子句指定查询范围,可指定类名,如java.lang.String、char[]、[Ljava.io.File;(File数组)。where子句用于指定查询条件。

这里简单测试一下,感兴趣的朋友可以再深入研究一下。

5、R Console 页面,这个是新加的窗口,支持 R 堆信息查看。

Threads

在 Threads 页面可以提供详细的线程信息,点击右上角的“Thread Dump”按钮,可以导出当前所有线程的堆栈信息(相当于 jstack)。

如果 VisualVM 在当前程序中找到死锁,则会在该页面很显眼地做出提示,如下图所示:

Sampler

在 “Sampler”页面下,有两个采样器,分别代表 CPU 和内存这两个性能采样器,用于实时监控程序信息。CPU 采样器可以将 CPU 占用时间定位到方法,内存采样器可以查看当前程序的堆信息。

这里我们以上面用到的死锁代码作为测试案例。

public class SyncDeadLock {

  private static Object objectA = new Object();
  private static Object objectB = new Object();

  public static void main(String[] args) {
    new SyncDeadLock().deadLock();
  }

  private void deadLock() {
    Thread thread1 = new Thread(new Runnable() {
      @Override
      public void run() {
        synchronized (objectA) {
          try {
            System.out.println(Thread.currentThread().getName() + " get objectA ing!");
            Thread.sleep(500);
          } catch (Exception e) {
            e.printStackTrace();
          }
          System.out.println(Thread.currentThread().getName() + " need objectB! Just waiting!");
          synchronized (objectB) {
            System.out.println(Thread.currentThread().getName() + " get objectB ing!");
          }
        }
      }
    }, "thread1");

    Thread thread2 = new Thread(() -> {
      synchronized (objectB) {
        try {
          System.out.println(Thread.currentThread().getName() + " get objectB ing!");
          Thread.sleep(500);
        } catch (Exception e) {
          e.printStackTrace();
        }
        System.out.println(Thread.currentThread().getName() + " need objectA! Just waiting!");
        synchronized (objectA) {
          System.out.println(Thread.currentThread().getName() + " get objectA ing!");
        }
      }
    }, "thread2");

    thread1.start();
    thread2.start();
  }
}

启动程序,然后进入“Sampler”页面,点击”CPU“按钮,得到如下内容:

上面出现的 Monitor Ctrl-Break,大家可能不明白是个什么东西。这里简单提一下,这个线程是在 IDEA 中才有的,而且还是用 run 启动方式才会出现,如果是 debug 启动方式,则不会出现。

比如在上面 main 方法中增加如下代码:

ThreadGroup currentGroup =
  Thread.currentThread().getThreadGroup();
int noThreads = currentGroup.activeCount();
Thread[] lstThreads = new Thread[noThreads];
currentGroup.enumerate(lstThreads);
for (int i = 0; i < noThreads; i++) {
  System.out.println("线程号:" + i + " = " + lstThreads[i].getName());
}

控制台会输出如下内容:

线程号:0 = main
线程号:1 = Monitor Ctrl-Break
线程号:2 = thread1
线程号:3 = thread2

我们接着对上图内容进行分析,可以发现 SyncDeadLock.run() 方法占用了大量的 CPU 时间,那么就可以定位到对应的代码,并加以改进。

接着来使用内存采样器,可以实时查看系统中实例的分布情况。

Profiler

在 Profiler 页签中,VisualVM 提供了程序运行期间方法级的处理器执行时间分析以及内存分析。做 Profiling 分析肯定会对程序运行性能有比较大的影响,所以一般不在生产环境使用这项功能,或者改用 JMC 来完成,JMC 的 Profiling 能力更强,对应用的影响非常轻微。

这里有四个选择:CPU、Memory、JDBC、Locks,不过在实际测试过程中,点击发现没有什么反应,本地控制台报错“Profiler Agent Warning: JVMTI classLoadHook: class name is null.“,也没找到解决方案。

市面上还有一款叫做 JProfiler 的分析工具,比 VirtualVM 要更详细,更专业,基本上覆盖了 VirtualVM 的功能点,还有一些更细致的功能,精确到代码某一行,不过是个收费软件,以后有机会用得到再研究一下。

Visual GC

JVisualVM 工具的 “VisualGC” 插件提供了基本的 JMX客户端功能, 还实时显示出 GC事件以及各个内存空间的使用情况。

Visual GC 插件常用来监控本机运行的Java程序, 比如开发者和性能调优专家经常会使用此插件, 以快速获取程序运行时的GC信息。

关于 Visual GC 插件的使用推荐阅读:Visual GC 插件使用 ,文章还介绍了 Spaces、Graphs 和 Histogram 这三块区域的含义。

首先我们看一下程序结束后在 Visual GC 的展示图:

根据上图可知:

  • 我们设置的堆空间大小为 60M,Eden 和老年代的内存大小按照 1:2 的比例进行分配;

  • Compile Time:编译情况 748 compoles - 853.953ms 表示编译总数为 748,编译总耗时为 853.953ms。 一个脉冲表示一次 JIT 编译,脉冲越宽表示编译时间越长。

  • Class Loader Time:类加载情况 1621 loaded,51 unloaded - 225.812ms表示已加载的数量为 1621,卸载的数量为 51,耗时为 225.812ms。

  • GC Time:总的(包含新生代和老年代)gc情况记录 52 collections,1.916s Last Cause:Allocation Failure表示一共经历了 52 次 GC(包含Minor GC和Full GC),总共耗时 1.916s。

  • Eden Space:新生代 Eden 区内存使用情况 (19.000M,15.000M): 530.28K,4 collections,27.792ms表示 Eden 区的最大容量为 19M,当前容量为 15M,当前已使用15M,从开始监控到现在在该内存区域一共发生了 4 次 gc(Minor GC),gc 总耗时为 27.792ms。

  • Survivor 0和Survivor 1:新生代的两个Survivor区内存使用情况 (6.500M,2.500M):0M表示该Survivor区的最大容量为 6.5M,当前已用 0M。

  • Old Gen:老年代内存使用情况 (40.000M,40.000M):1.829M,48 collections,1.889s表示老年区的最大容量为 40M,当前容量为 40 M,当前已用 1.829M,从开始监控到现在在该内存区域一共发生了 48 次gc(Full GC),gc 总耗时为 1.889s,换算下可以看出单次 Full GC 要比 Minor GC 耗时长很多。

  • Metaspace:方法区内存使用情况 (1.008G,9.125M):8.473M表示方法区最大容量为1.008G,当前容量为 9.125M,当前使用量为 8.473M。

下面我们展示一下程序运行过程的动图展示:

GCeasy

GCeasy 是一款在线的 GC日志分析器,可以通过GC日志分析进行内存泄漏检测、GC暂停原因分析、JVM 配置建议优化等功能,而且是可以免费使用的(有一些服务是收费的)。

将我们得到 gc log 文件上传上去,然后点击分析按钮,稍等片刻就会出结果。这里展示部分截图:

下述图片中,可以点击左侧按钮,显示不同的内容,比如说点击 Old Gen,

下面这张图就更加详细了,与 GCViewer 相比展示更加直观。

总结

本文介绍了三种工具来分析 GC 日志,以及通过日志关注哪些信息。当然文中的案例比较简单,实际应用肯定复杂的多,后续我会再找机会出一篇生产过程中 GC 日志分析的文章。