记一次Java OOM故障排查过程

背景

最近，我司系统出现java.lang.OutOfMemoryError: Java heap space异常，导致服务不能正常使用。为了搞清楚异常发生的根因，我利用闲暇时间进行了一次排查。这篇文章将整个排查过程详细地记录下来，方便以后翻阅。

---

初步分析

在JVM中，当系统98%的时间都用于GC且Heap Size不足2%时，将会抛出java.lang.OutOfMemoryError: Java heap space异常（OOM）。所以，当我们看到OOM异常时，可以初步判定，JVM大部分时间都用于GC，不能正常提供服务。

在Java中new对象时，JVM会检查剩余的空间是否够用，如果申请的内存空间大于剩余空间，JVM就会发生GC，回收空间供新对象使用。如果JVM大部分时间都花在GC上，那说明分配给JVM的内存空间也快被耗尽了。这个时候，做再多的GC也没用，因为分配给JVM的内存耗尽了。系统只能苦苦挣扎，幻想着GC可以释放一些空间。

现在，我们已经可以初步判定：OOM异常是由于JVM内存耗尽所致。这时我们自然会想，既然分配给JVM内存不够用，那么多分配一点不就行了。确实，现实中我们可以通过增加内存的容量来缓解内存不足的问题。但是，一台机器上的内存也是有限的，我们不可能无限增加内存。这种方案只能解决短期的问题，无法根治。

那么，有没有什么办法和工具可以帮助我们深入分析OOM出现的原因，从而根本上解决这个问题呢？

答案是：有的。

下面我将使用jps+jmap+jstat+jhat+MAT等工具来分析这个问题的根因。

---

根因分析

jps、jstat、jmap和jhat都是JDK自带的分析工具，在$JAVA_HOME/bin运行命令即可分析JVM，小巧便捷。
MAT(Eclipse Memory Analyzer)是一款内存分析工具，功能强大，分析高效便捷。

使用jps查询vmid

首先，我们使用jps命令查询vmid。jps 命令是使用最频繁的一个命令。使用该命令可以帮助我们快速查出当前主机上运行的虚拟机vmid, vmid对我们后续分析至关重要。
示例：如下图所示，jps 命令查询出来一条vmid为1的进程。

使用虚拟机监控命令jstat

获取JVM的PID后，使用jstat监控当前虚拟机的状态
jstat的使用方式可以通过命令jstat -help查看, 如下

[root@*-zhfq6]# jstat -help
Usage: jstat -help|-options
       jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]
Definitions:
  <option>      An option reported by the -options option
  <vmid>        Virtual Machine Identifier. A vmid takes the following form:
                     <lvmid>[@<hostname>[:<port>]]
                Where <lvmid> is the local vm identifier for the target
                Java virtual machine, typically a process id; <hostname> is
                the name of the host running the target Java virtual machine;
                and <port> is the port number for the rmiregistry on the
                target host. See the jvmstat documentation for a more complete
                description of the Virtual Machine Identifier.
  <lines>       Number of samples between header lines.
  <interval>    Sampling interval. The following forms are allowed:
                    <n>["ms"|"s"]
                Where <n> is an integer and the suffix specifies the units as 
                milliseconds("ms") or seconds("s"). The default units are "ms".
  <count>       Number of samples to take before terminating.
  -J<flag>      Pass <flag> directly to the runtime system.

jstat 命令格式：jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]
option表示需要监控的内容，vmid就是ps 命令查询出来的虚拟机id, interval是监控间隔，count表示总共展示次数。其中通过命令jstat -options可以找到所有的option，如下：

[root@*-zhfq6]# jstat -options
-class
-compiler
-gc
-gccapacity # GC内存使用情况
-gccause # GC原因
-gcmetacapacity
-gcnew
-gcnewcapacity #新生代内存容量使用情况
-gcold
-gcoldcapacity  #新生代内存容量使用情况
-gcutil #内存使用率情况
-printcompilation

示例：jstat -gcutil 1 1s 10

这条命令将监控vmid为1的虚拟机的内存空间使用率情况（-gcutil），时间间隔为1s，总共展示10次。
查询结果表明：这台服务器的新生代Eden区（E，表示Eden）使用了36.5%的空间，两个Survivor区（S0、S1，表示Survivor0、Survivor1）分别是0和6.37%，老年代（O，表示Old）使用了65.15%。程序运行以来共发生Minor GC（YGC，表示Young GC）107次，总耗时4.704秒，发生Full GC（FGC，表示Full GC）56次，Full GC总耗时3.324秒，总的耗时（GCT，表示GC Time）为8.028秒

使用jmap生成Heap Dump文件

使用jmap -dump命令导出Heap Dump文件，jmap指令的用法请参考命令jmap -help

示例：jmap -dump:format=b,file=java-1.hprof 1导出vmid为1的jvm的Heap Dump文件，文件名叫java-1.hprof

[root@*-zhfq6]# jmap -dump:format=b,file=java-1.hprof 1
Dumping heap to /var/log/java-1.hprof ...
Heap dump file created

生成Dump文件后，下载到本地，以备后续分析使用。

分析Heap Dump文件

上一步已经导出了Heap Dump文件，现在到了最为关键的一步：分析Heap Dump文件。

使用jhat分析

jhat是JDK自带的一个Dump分析工具，使用方法简单。运行命令jhat java-1.hprof即可分析我们上一步导出的java-1.hprof文件。其工作原理是，启动一个端口号为7000的http服务，通过浏览器输入http://localhost:7000/就可以访问查看结果。该工具的缺陷是不太容易找到问题出现的地方，需要多探索才行。下面只做jhat使用的简单介绍，不做深究，有兴趣的朋友可以自己深入了解。

使用MAT分析

MAT(Eclipse Memory Analyzer)，MAT是一款内存分析工具。为了使用MAT, 首先需要从官网下载合适的版本https://www.eclipse.org/mat/downloads.php。下载后本地解压，直接运行即可。

1. 下载MAT

2. 解压、运行MAT

3. MAT打开Heap Dump文件

4. 分析Dump
   打开Heap Dump文件后，从Leak Suspect中可以看到Problem Suspect 1中com.dianping.cat.message.io.TcpSocketSender的实例占用了93.83%的内存空间，大约有458M, 而我们的配置为-Xmx512m -Xms512m。直觉告诉我们，这个对象的实例占用大部分的内存空间，这是不合理的。为了一探究竟，点击Details进入详情后，可以看到该实例com.dianping.cat.message.io.TcpSocketSender @ 0xeaca04c0的属性m_queue占用了大部分空间。接着，我们依次点击List Objects和with outgoing references(见下图)，进入com.dianping.cat.message.io.TcpSocketSender @ 0xeaca04c0详情, 在list_objects中，我们展开属性后看到：items这个数组几乎占用了整个com.dianping.cat.message.io.TcpSocketSender @ 0xeaca04c0的空间，items长度为5000，其中有1190已填充数据，此外，每个com.dianping.cat.message.spi.internal.DefaultMessageTree的大小竟然达到约0.38M(404,368Bytes)！0.38M*1190 和 458M正好差不多。到此为止，基本可以断定：由于DefaultMessageTree太大，整个内存空间基本上都被com.dianping.cat.message.io.TcpSocketSender @ 0xeaca04c0占用，导致内存不足。

   
   

TcpSocketSender 实体结构如下：

package com.dianping.cat.message.io;

@Named
public class TcpSocketSender implements Task, MessageSender, LogEnabled {
    public static final int SIZE = ApplicationSettings.getQueueSize();
    private static final int MAX_CHILD_NUMBER = 200;
    private static final int MAX_DURATION = 30000;
    public static final long HOUR = 3600000L;
    private MessageCodec m_codec = new NativeMessageCodec();
    @Inject
    private MessageStatistics m_statistics;
    @Inject
    private ClientConfigManager m_configManager;
    @Inject
    private MessageIdFactory m_factory;
    private MessageQueue m_queue;
    private MessageQueue m_atomicQueue;
    private ChannelManager m_channelManager;
    private Logger m_logger;
    private boolean m_active;
    private AtomicInteger m_errors;

    public TcpSocketSender() {
        this.m_queue = new DefaultMessageQueue(SIZE);
        this.m_atomicQueue = new DefaultMessageQueue(SIZE);
        this.m_errors = new AtomicInteger();
    }
}

5. 解决思路
   通过上一步的分析，再结合实际代码，我们发现，上述内存异常占用是系统引入Cat监控后所致。本质原因就是Cat单个消息内容太大（约0.38M），占领了大部分内存。其中，items的长度为5000，每个大小约0.38M，填满整个items大概需要约1.86G的空间。极端情况下，假设items都被填满，则至少需要1.86G的内存大小。综上，有两个思路可供参考：
   A: 设法缩小单条Cat消息的大小
   B: 扩大-Xmx的配置，结合实际最少为2G(>1.86G)

总结

此文结合工作中遇到的OOM问题，首先从理论上分析可能导致OOM的原因；接着介绍了JDK自带的jps、jstat、jmap、jhat等工具；后面又结合实际问题简单介绍了一下jhat和MAT分析Heap Dump的过程。最终，我们得出此案例中OOM出现的原因是由于Cat的消息过长，并给出解决思路。