35 分析定位Java问题，一定要用好这些工具（二）

其实，工具正是帮助我们深入到框架和组件内部，了解其运作方式和原理的重要抓手。所以，我们一定要用好它们。

本篇将介绍如何使用JVM堆转储的工具MAT来分析OOM问题，以及如何使用全能的故障诊断工具Arthas来分析、定位高CPU问题。

使用MAT分析OOM问题

对于排查OOM问题、分析程序堆内存使用情况，最好的方式就是分析堆转储。

堆转储，包含了堆现场全貌和线程栈信息（Java 6 Update 14开始包含）可以对程序内有多少对象、哪些是大对象一目了然，就好似得到了病人在某个瞬间的全景核磁影像，可以拿着慢慢分析，进而定位问题。

Java的OutOfMemoryError是比较严重的问题，需要分析出根因，所以对生产应用一般都会这样设置JVM参数，方便发生OOM时进行堆转储：

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=.

我推荐使用Eclipse的Memory Analyzer（也叫做MAT）做堆转储的分析。你可以点击这个链接，下载MAT。

使用MAT分析OOM问题，一般可以按照以下思路进行：

1. 通过支配树功能或直方图功能查看消耗内存最大的类型，来分析内存泄露的大概原因；
2. 查看那些消耗内存最大的类型、详细的对象明细列表，以及它们的引用链，来定位内存泄露的具体点；
3. 配合查看对象属性的功能，可以脱离源码看到对象的各种属性的值和依赖关系，帮助我们理清程序逻辑和参数；
4. 辅助使用查看线程栈来看OOM问题是否和过多线程有关，甚至可以在线程栈看到OOM最后一刻出现异常的线程。

比如，我手头有一个OOM后得到的转储文件java_pid29569.hprof，现在要使用MAT的直方图、支配树、线程栈、OQL等功能来分析此次OOM的原因。

首先，用MAT打开后先进入的是概览信息界面，可以看到整个堆是437.6MB：

那么，这437.6MB都是什么对象呢？

如图所示，工具栏的第二个按钮可以打开直方图，直方图按照类型进行分组，列出了每个类有多少个实例，以及占用的内存。可以看到，char[]字节数组占用内存最多，对象数量也很多，结合第二位的String类型对象数量也很多，大概可以猜出（String使用char[]作为实际数据存储）程序可能是被字符串占满了内存，导致OOM。

我们继续分析下，到底是不是这样呢。

在char[]上点击右键，选择List objects->with incoming references，就可以列出所有的char[]实例，以及每个char[]的整个引用关系链：

随机展开一个char[]，如下图所示：

接下来，我们按照红色框中的引用链来查看，尝试找到这些大char[]的来源：

• 在①处看到，这些char[]几乎都是10000个字符、占用20000字节左右（char是UTF-16，每一个字符占用2字节）；
• 在②处看到，char[]被String的value字段引用，说明char[]来自字符串；
• 在③处看到，String被ArrayList的elementData字段引用，说明这些字符串加入了一个ArrayList中；
• 在④处看到，ArrayList又被FooService的data字段引用，这个ArrayList整个RetainedHeap列的值是431MB。

Retained Heap（深堆）代表对象本身和对象关联的对象占用的内存，Shallow Heap（浅堆）代表对象本身占用的内存。比如，我们的FooService中的data这个ArrayList对象本身只有16字节，但是其所有关联的对象占用了431MB内存。这些就可以说明，肯定有哪里在不断向这个List中添加String数据，导致了OOM。

左侧的蓝色框可以查看每一个实例的内部属性，图中显示FooService有一个data属性，类型是ArrayList。

如果我们希望看到字符串完整内容的话，可以右键选择Copy->Value，把值复制到剪贴板或保存到文件中：

这里，我们复制出的是10000个字符a（下图红色部分可以看到）。对于真实案例，查看大字符串、大数据的实际内容对于识别数据来源，有很大意义：

看到这些，我们已经基本可以还原出真实的代码是怎样的了。

其实，我们之前使用直方图定位FooService，已经走了些弯路。你可以点击工具栏中第三个按钮（下图左上角的红框所示）进入支配树界面（有关支配树的具体概念参考这里）。这个界面会按照对象保留的Retained Heap倒序直接列出占用内存最大的对象。

可以看到，第一位就是FooService，整个路径是FooSerice->ArrayList->Object[]->String->char[]（蓝色框部分），一共有21523个字符串（绿色方框部分）：

这样，我们就从内存角度定位到FooService是根源了。那么，OOM的时候，FooService是在执行什么逻辑呢？

为解决这个问题，我们可以点击工具栏的第五个按钮（下图红色框所示）。打开线程视图，首先看到的就是一个名为main的线程（Name列），展开后果然发现了FooService：

先执行的方法先入栈，所以线程栈最上面是线程当前执行的方法，逐一往下看能看到整个调用路径。因为我们希望了解FooService.oom()方法，看看是谁在调用它，它的内部又调用了谁，所以选择以FooService.oom()方法（蓝色框）为起点来分析这个调用栈。

往下看整个绿色框部分，oom()方法被OOMApplication的run方法调用，而这个run方法又被SpringAppliction.callRunner方法调用。看到参数中的CommandLineRunner你应该能想到，OOMApplication其实是实现了CommandLineRunner接口，所以是SpringBoot应用程序启动后执行的。

以FooService为起点往上看，从紫色框中的Collectors和IntPipeline，你大概也可以猜出，这些字符串是由Stream操作产生的。再往上看，可以发现在StringBuilder的append操作的时候，出现了OutOfMemoryError异常（黑色框部分），说明这这个线程抛出了OOM异常。

我们看到，整个程序是Spring Boot应用程序，那么FooService是不是Spring的Bean呢，又是不是单例呢？如果能分析出这点的话，就更能确认是因为反复调用同一个FooService的oom方法，然后导致其内部的ArrayList不断增加数据的。

点击工具栏的第四个按钮（如下图红框所示），来到OQL界面。在这个界面，我们可以使用类似SQL的语法，在dump中搜索数据（你可以直接在MAT帮助菜单搜索OQL Syntax，来查看OQL的详细语法）。

比如，输入如下语句搜索FooService的实例：

SELECT * FROM org.geekbang.time.commonmistakes.troubleshootingtools.oom.FooService

可以看到只有一个实例，然后我们通过List objects功能搜索引用FooService的对象：

得到以下结果：

可以看到，一共两处引用：

• 第一处是，OOMApplication使用了FooService，这个我们已经知道了。
• 第二处是一个ConcurrentHashMap。可以看到，这个HashMap是DefaultListableBeanFactory的singletonObjects字段，可以证实FooService是Spring容器管理的单例的Bean。

你甚至可以在这个HashMap上点击右键，选择Java Collections->Hash Entries功能，来查看其内容：

这样就列出了所有的Bean，可以在Value上的Regex进一步过滤。输入FooService后可以看到，类型为FooService的Bean只有一个，其名字是fooService：

到现在为止，我们虽然没看程序代码，但是已经大概知道程序出现OOM的原因和大概的调用栈了。我们再贴出程序来对比一下，果然和我们看到得一模一样：

@SpringBootApplication
public class OOMApplication implements CommandLineRunner {
    @Autowired
    FooService fooService;
    public static void main(String[] args) {
        SpringApplication.run(OOMApplication.class, args);
    }
    @Override
    public void run(String... args) throws Exception {
        //程序启动后，不断调用Fooservice.oom()方法
        while (true) {
            fooService.oom();
        }
    }
}
@Component
public class FooService {
    List<String> data = new ArrayList<>();
    public void oom() {
        //往同一个ArrayList中不断加入大小为10KB的字符串
        data.add(IntStream.rangeClosed(1, 10_000)
                .mapToObj(__ -> "a")
                .collect(Collectors.joining("")));
    }
}

到这里，我们使用MAT工具从对象清单、大对象、线程栈等视角，分析了一个OOM程序的堆转储。可以发现，有了堆转储，几乎相当于拿到了应用程序的源码+当时那一刻的快照，OOM的问题无从遁形。

使用Arthas分析高CPU问题

Arthas是阿里开源的Java诊断工具，相比JDK内置的诊断工具，要更人性化，并且功能强大，可以实现许多问题的一键定位，而且可以一键反编译类查看源码，甚至是直接进行生产代码热修复，实现在一个工具内快速定位和修复问题的一站式服务。今天，我就带你使用Arthas定位一个CPU使用高的问题，系统学习下这个工具的使用。

首先，下载并启动Arthas：

curl -O https://alibaba.github.io/arthas/arthas-boot.jar
java -jar arthas-boot.jar

启动后，直接找到我们要排查的JVM进程，然后可以看到Arthas附加进程成功：

[INFO] arthas-boot version: 3.1.7
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 12707
  [2]: 30724 org.jetbrains.jps.cmdline.Launcher
  [3]: 30725 org.geekbang.time.commonmistakes.troubleshootingtools.highcpu.HighCPUApplication
  [4]: 24312 sun.tools.jconsole.JConsole
  [5]: 26328 org.jetbrains.jps.cmdline.Launcher
  [6]: 24106 org.netbeans.lib.profiler.server.ProfilerServer
3
[INFO] arthas home: /Users/zhuye/.arthas/lib/3.1.7/arthas
[INFO] Try to attach process 30725
[INFO] Attach process 30725 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'

wiki https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version 3.1.7
pid 30725
time 2020-01-30 15:48:33

输出help命令，可以看到所有支持的命令列表。今天，我们会用到dashboard、thread、jad、watch、ognl命令，来定位这个HighCPUApplication进程。你可以通过官方文档，查看这些命令的完整介绍：

dashboard命令用于整体展示进程所有线程、内存、GC等情况，其输出如下：

可以看到，CPU高并不是GC引起的，占用CPU较多的线程有8个，其中7个是ForkJoinPool.commonPool。ForkJoinPool.commonPool是并行流默认使用的线程池。所以，此次CPU高的问题，应该出现在某段并行流的代码上。

接下来，要查看最繁忙的线程在执行的线程栈，可以使用thread -n命令。这里，我们查看下最忙的8个线程：

thread -n 8

输出如下：

可以看到，由于这些线程都在处理MD5的操作，所以占用了大量CPU资源。我们希望分析出代码中哪些逻辑可能会执行这个操作，所以需要从方法栈上找出我们自己写的类，并重点关注。

由于主线程也参与了ForkJoinPool的任务处理，因此我们可以通过主线程的栈看到需要重点关注org.geekbang.time.commonmistakes.troubleshootingtools.highcpu.HighCPUApplication类的doTask方法。

接下来，使用jad命令直接对HighCPUApplication类反编译：

jad org.geekbang.time.commonmistakes.troubleshootingtools.highcpu.HighCPUApplication

可以看到，调用路径是main->task()->doTask()，当doTask方法接收到的int参数等于某个常量的时候，会进行1万次的MD5操作，这就是耗费CPU的来源。那么，这个魔法值到底是多少呢？

你可能想到了，通过jad命令继续查看User类即可。这里因为是Demo，所以我没有给出很复杂的逻辑。在业务逻辑很复杂的代码中，判断逻辑不可能这么直白，我们可能还需要分析出doTask的“慢”会慢在什么入参上。

这时，我们可以使用watch命令来观察方法入参。如下命令，表示需要监控耗时超过100毫秒的doTask方法的入参，并且输出入参，展开2层入参参数：

watch org.geekbang.time.commonmistakes.troubleshootingtools.highcpu.HighCPUApplication doTask ‘{params}’ ‘#cost>100’ -x 2

可以看到，所有耗时较久的doTask方法的入参都是0，意味着User.ADMN_ID常量应该是0。

最后，我们使用ognl命令来运行一个表达式，直接查询User类的ADMIN_ID静态字段来验证是不是这样，得到的结果果然是0：

[arthas@31126]$ ognl ‘@org.geekbang.time.commonmistakes.troubleshootingtools.highcpu.User@ADMIN_ID’

@Integer[0]

需要额外说明的是，由于monitor、trace、watch等命令是通过字节码增强技术来实现的，会在指定类的方法中插入一些切面来实现数据统计和观测，因此诊断结束要执行shutdown来还原类或方法字节码，然后退出Arthas。

在这个案例中，我们通过Arthas工具排查了高CPU的问题：

• 首先，通过dashboard + thread命令，基本可以在几秒钟内一键定位问题，找出消耗CPU最多的线程和方法栈；
• 然后，直接jad反编译相关代码，来确认根因；
• 此外，如果调用入参不明确的话，可以使用watch观察方法入参，并根据方法执行时间来过滤慢请求的入参。

• 可见，使用Arthas来定位生产问题根本用不着原始代码，也用不着通过增加日志来帮助我们分析入参，一个工具即可完成定位问题、分析问题的全套流程。

  对于应用故障分析，除了阿里Arthas之外，还可以关注去哪儿的Bistoury工具，其提供了可视化界面，并且可以针对多台机器进行管理，甚至提供了在线断点调试等功能，模拟IDE的调试体验。

  重点回顾

  最后，我再和你分享一个案例吧。

  有一次开发同学遇到一个OOM问题，通过查监控、查日志、查调用链路排查了数小时也无法定位问题，但我拿到堆转储文件后，直接打开支配树图一眼就看到了可疑点。Mybatis每次查询都查询出了几百万条数据，通过查看线程栈马上可以定位到出现Bug的方法名，然后来到代码果然发现因为参数条件为null导致了全表查询，整个定位过程不足5分钟。

  从这个案例我们看到，使用正确的工具、正确的方法来分析问题，几乎可以在几分钟内定位到问题根因。今天，我和你介绍的MAT正是分析Java堆内存问题的利器，而Arthas是快速定位分析Java程序生产Bug的利器。利用好这两个工具，就可以帮助我们在分钟级定位生产故障。

  思考与讨论

  1. 在介绍线程池的时候，我们模拟了两种可能的OOM情况，一种是使用Executors.newFixedThreadPool，一种是使用Executors.newCachedThreadPool，你能回忆起OOM的原因吗？假设并不知道OOM的原因，拿到了这两种OOM后的堆转储，你能否尝试使用MAT分析堆转储来定位问题呢？
  2. Arthas还有一个强大的热修复功能。比如，遇到高CPU问题时，我们定位出是管理员用户会执行很多次MD5，消耗大量CPU资源。这时，我们可以直接在服务器上进行热修复，步骤是：jad命令反编译代码->使用文本编辑器（比如Vim）直接修改代码->使用sc命令查找代码所在类的ClassLoader->使用redefine命令热更新代码。你可以尝试使用这个流程，直接修复程序（注释doTask方法中的相关代码）吗？