欢迎大家来到IT世界,在知识的湖畔探索吧!

本文为《深入学习 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
复制代码

欢迎大家来到IT世界,在知识的湖畔探索吧!

导出 gc log

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

欢迎大家来到IT世界,在知识的湖畔探索吧!-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。

欢迎大家来到IT世界,在知识的湖畔探索吧!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 日志分析的文章。

原文链接：https://juejin.cn/post/7081622325304492045