By Valleylord

更新日期:

文章目录

本文主要使用Eclipse的MAT工具和JDK自带的jvisualvm工具来分析程序运行异常之后的堆dump文件，以找到程序出错的原因。

Eclipse的MAT(Memory Analyzer Tool) 是基于heap dumps来进行分析的，它的分析速度比jhat快，分析结果是图形界面显示，比java内置jhat的可读性更高。官网上有下载地址，也可以在Eclipse Marketplace中找到安装，安装可以参考这里。

成功安装完之后，打开Eclipse，通过Window->Open Perspective->Memory Analysis，进入MAT的工作面板，如果看不到Memory Analysis，说明没有安装成功。然后就可以通过File->Open Heap Dump...来打开待分析的堆dump文件。

打开oom.prof（一般是.hprof扩展名）文件，产生该文件的程序在运行时报OOM，之后看到如下概览（Overview）界面，

直觉的反应是，堆的总大小是5.8M，但是有一个类的对象占用了其中的5.4M，很大概率，问题就在这个类上。切换到柱状图模式，并按照Shallow Heap1倒排序，如下

可以看到有一个char[]的类占用了过多的内存，有1026个对象，内存占用量第一，占用第二的对象所需内存不到它的1%。对这个类，右键->List objects->with outgoing reference，可以看到这个类的对象，和对象引用到的其他对象（如果选with incoming reference，则是这个类的对象，和引用到这些对象的其他对象），同样，也按照Shallow Heap倒排序，如下，

可以看到有很多char[40090]的对象，大约70+个，每个大小都是80k（80,192 Byte），所以这些对象的总大小就是80k*70=5400k，也就是5.4M，和最初在概览界面里面看到的5.4M吻合，再向下翻页，发现还有一些其他的char[]对象，不过都占用空间比较小，不构成压力，如下，

这些比较小的char[]对象，看了一些内容，都是一些不太常见的字符，猜测可能是和程序字符集相关的字符编码。

下面猜测一下这个程序的逻辑和发生OOM的原因。首先，程序的堆文件大小总共是5.8M，可以猜测，该程序在运行时设置了JVM参数-Xmx 6M，也就是最大堆大小是6M，类似这样的选项。然后，程序处理的逻辑应该大致是这样，在一个循环中，不停的新增char[]，并且不做垃圾回收，所产生的对象内容是从0开始的整数序列toString的结果，因为可以明显看出，这些对象的内容是重复的。在循环重复执行了70+次的时候，再次新增char[]对象的时候，堆内存不足，发生了OOM，而图中的char[36862]对象，很可能就是最后发生内存不足的那个对象，因为这个对象的前部分内容是和其他对象的内容一致的，而长度却不足。如果的确是这样的话，这个char[]对象的长度实际上应该是不断增长的，那么这个对象很有可能是String类型，因为String是包含一个char[]对象的。

实际上，该文件的domain tree页面，也印证了上述想法，如下

可以很明显的看到在ArrayList对象下面有个Object[88]的对象，这是应为ArrayList是用数组方式实现的，而在Object[88]对象下，有很多个String对象，这些对象每个占用1.32%的内存，总共占用了93.45%的内存，有了这些信息，不难分析出发生OOM的代码，应该是类似下面这样，

1
2
3
4
5
6
7
8
9
10
11
// 使用类似Java语法的伪代码
List<String> list = new ArrayList<String>();
String temp；
for(int i=0; i<88; i++){
  temp = null；
  for(int j=0; j<=10240; j++){   // 10240这个数字是根据40090和产生的数据是从0开始的整数这个假设推算出来的
    temp += Integer(i).toString;
  }
  list.add(temp);
}

到此，分析完毕。

下面，再用jvisualvm来分析一个Tomcat发生OOM的堆dump文件。

先运行jvisualvm，加载发生OOM的堆dump文件tomcat.hprof。可以看到概要视图，如下，

Tomcat负责管理连接的类是org.apache.catalina.session.StandardSession，因此只需要关心这个类有多少个实例。在类视图中，可以发现连接有9963个，如下，

对其右键->在实例视图中显示，可以看到具体的类结构

在OQL控制台视图中，可以使用OQL语言2，观察这些Session分别是什么什么时候建立的，如下，

1
select s.creationTime from org.apache.catalina.session.StandardSession s

查询的creationTime列就是Session建立的时间，使用一个长整型来保存，单位是毫秒ms。查询得到的结果大概是下面这样，

1
2
3
4
5
1403324645728
1403324645755
1403324645759
1403324645763
......

然后，我们可以分析，1秒中内建立的最多的连接是多少个，也就是Tomcat处理每秒的峰值。可以写一个Java程序来协助求解，这个程序需要打开tomcat.hprof文件，并用OQL引擎，在这个dump文件上执行OQL才能获取全部的记录。需要使用visualvm的一些库，这些库在JDK的安装目录下，主要是以下一些目录，

1
2
3
$JAVA_HOME/lib/visualvm/platform/lib/*.jar
$JAVA_HOME/lib/visualvm/profiler/modules/*.jar
$JAVA_HOME/lib/visualvm/visualvm/modules/*.jar

由于本例比较简单，实际上只用到了其中2个jar文件，分别是，

1
2
$JAVA_HOME/lib/visualvm/profiler/modules/org-netbeans-lib-profiler.jar
$JAVA_HOME/lib/visualvm/profiler/modules/org-netbeans-modules-profiler-oql.jar

完整的Java程序如下，

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
package problem2;
/* Use OQL in Java
 * should import follows to resolve dependencies
 * $JAVA_HOME/lib/visualvm/profiler/modules/org-netbeans-lib-profiler.jar
 * $JAVA_HOME/lib/visualvm/profiler/modules/org-netbeans-modules-profiler-oql.jar
 * ($JAVA_HOME is where you install your JDK)
 *
 * Passed under JDK 1.8 and 1.6
 */
import java.io.File;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import org.netbeans.lib.profiler.heap.HeapFactory;
import org.netbeans.modules.profiler.oql.engine.api.OQLEngine;
import org.netbeans.modules.profiler.oql.engine.api.OQLEngine.ObjectVisitor;
import org.netbeans.modules.profiler.oql.engine.api.OQLException;
public class Problem2 {
    public static void main(String[] args)
          throws FileNotFoundException, IOException, OQLException{
        final List<Long> listTimes = new ArrayList<Long>(10000);
        List<Integer> listOccurs = new ArrayList<Integer>(10000);
        String query = "select s.creationTime from"
                          + " org.apache.catalina.session.StandardSession s";
        OQLEngine instance = new OQLEngine(HeapFactory.createHeap(
                                    new File("tomcat.hprof")));
        ObjectVisitor visitor = new ObjectVisitor(){
            public boolean visit(Object o){
                listTimes.add(new Long(o.toString()));
                return false;
            }
        };
        instance.executeQuery(query, visitor);
        Collections.sort(listTimes);
        int distance;
        for (int i=0; i<listTimes.size(); i++){
        	distance = 0;
            for (int j = i+1; j<listTimes.size(); j++){
                distance = j-i;
                if (listTimes.get(j)-listTimes.get(i) > 1000){  // in 1000ms
                    break;
                }
            }
            listOccurs.add(new Integer(distance));
        }
        int maxDistance = 0;
        int maxIndex = 0;
        for (int i=0; i<listOccurs.size(); i++){
        	if(listOccurs.get(i) > maxDistance){
        		maxDistance = listOccurs.get(i);
        		maxIndex = i;
        	}
        }
        System.out.println("Between Time ["+listTimes.get(maxIndex)
        		+"] and ["+(listTimes.get(maxIndex)+1000)
        		+"], Max Requests is "+listOccurs.get(maxIndex)+".");
    }
}

上述程序的处理步骤是：先打开堆dump文件，并构造OQL引擎，接下来在OQL引擎上运行OQL获取所有的新建Session的时间点，存入listTimes，并排序。然后，以每个新建Session的时间点为起始点，计算1秒内有多少个新建的连接。最后，找到最大的那个连接数，并返回对应的起始时间点即可。当然，这个算法并没有很优化，但是也可以得到问题的解。程序输出如下，

1
Between Time [1403324651641] and [1403324652641], Max Requests is 865.

因此，在时间点1403324651641和1403324651641之间，最大的请求数是865次，这是Tomcat在这次运行中达到的峰值。

  1. Shallow Heap（浅堆）表示该对象本身占用的内存大小，Retained Heap（深堆）表示该对象释放之后，可以释放的所有内存。因为一个对象可能引用别的对象，当该对象释放的时候，被引用的对象可能不再被引用了，因此也会被释放，所以一般有，Retained Heap>=Shallow Heap。具体Retained Heap会释放多少空间和JVM中的支配树概念有关，不再赘述。↩

  2. http://visualvm.java.net/oqlhelp.html↩

文章目录

欢迎来到Valleylord的博客！

本博的文章尽量原创。