haoweishow Blog

ESB/Java

OOM故障分析-案例1

背景


  • 生产环境,应用刚上线,几乎每天一次OOM.
  • 操作系统: AIX 6.1
  • JDK版本: J2RE 5.0 IBM J9 2.3 AIX ppc64-64 build j9vmap6423-20100808
  • JVM参数: -Xmx2048m -Xms2048m 无其它参数设置,采用JVM默认设置
  • 分析工具: jca455.jar ibm_ha446.jar

分析1


第一次出现故障,发过来java进程的dump文件,3组12个文件:

  • 4个heapdump.xxxx.phd;
  • 4个javacore.xxxx.txt;
  • 4个Snap.xxxx.trc

使用IBM HA工具分析phd文件

打开[Analysis View]如下:

  • 通过HA的分析,结果很明显,java/util/Stack里的数据量超大,占用内存92.2%
  • 这个Stack是自定义的XML解析器里的一个属性,用于存储在解析过程中存储XML节点信息
  • 看到这里,如果对应用了解的话,是能够找到程序哪个模块调用这个XML解析器,可是我不了解这个应用,而且不在现场
  • 接下来的分析过程,包括未来几天陆续出现的OOM,分析其中的phd文件都是同样的现象,Stack里的数据量超大,都是超过90%的堆内存占用

打开[Root List]如下:

  • 排名第一的是XML解析器,其它的对象内存使用都很小

打开[Tree View]如下:

  • 这里有个疑问,为什么这个解析器是root object,明明是有线程调用这个解析器进行XML解析的
  • 关于JVM的root object还是不了解!!

使用IBM JCA工具分析javacore文件

打开[Thread Dump List]如下:

  • 在网上查找关于javacore文件相关资料的时候,网上有个案例,可以根据这里的WARN提示就定位出产生OOM的线程
  • 我的这个案例不一样了,可以看到这几个WARN涉及的线程申请的内存都很小,说明这个时候内存已经被使用殆尽,这几个线程不是导致OOM的真正原因

打开[Thread Status]如下:

  • 这里显示的线程信息,与OOM没有关系,但是可以看到这个应用里的一些问题,很多线程都处于Blocked状态,左下角框起来的仅仅是部分,几乎都是由于日志记录引起的
  • 这个应用由于业务场景的需要,需要记录交易的详细日志.后来到现场看到系统的日志,一共2个还是3个日志文件,每个小时切换一个日志文件.
  • 近300个线程,将大量的交易日志写到两个文件中,锁的竞争可想而知;这里其实也有优化的空间的,可以根据某些关键字,将日志文件分类,就像数据库表分区一样;相信300个线程写分散到20个日志文件中,性能的提升应该是可见的.

初步分析

  • 至此,导致OOM的直接原因是解析XML的时候,该解析器的Stack里的数据超大
  • 而Stack里的数据超大,是不是解析过程中陷入某种循环无法退出导致呢?

分析2

终于到现场进行分析了,很庆幸的是,在现场的性能测试环境能够重现该问题.
分析该解析器:

  • 该类在解析XML的时候,用Stack来存储节点的信息
  • 遇到节点开始,将节点的对象入栈,遇到节点结束,弹栈
  • 因此造成Stack数据量大就这能出现在入栈的地方了.
  • 所以在入栈之后,增加判断,当栈的size超过阀值之后,打印出一些信息
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
//伪代码  
public class xxxxReader extends xxxx{
    private Stack stack = new Stack();
    /**************************************************************/
    public void debug(){
        if(stack.size()>1000){
            System.out.println("stacksize:"+stack.size());
            Thread.dumpStack();//打印栈信息,就知道哪个模块调用到这个解析器
        }
    }
    /**************************************************************/
    public void startElement(){
        stack.push(obj);
        debug();
    }
    public void endElement(){
        stack.pop();
    }
    public void startArray(){
        stack.push(obj);
        debug();
    }
    public void endArray(){
        stack.pop();
    }
}
  • 在性能测试环境打上该类,重启,再次进行压力测试.
  • 半个小时左右的样子,出现OOM,经过统计System.out和Thread.dumpStack()的日志,锁定了两个调用的地方.
  • 再次修改这个解析器,加入临时属性,用于保存要解析的报文,这样在出现超大Stack的时候,可以将报文打印出来,这个代码就不贴了.
  • 重启,再压,得到异常时候的报文,该报文的结构正常,应该不会导致死循环,于是在本地编写解析器的测试代码,解析该报文1次,1万次都正常.
  • 难道是多线程的问题呢?
  • 修改测试代码,两个线程,同时各执行1万次,问题重现了!!!!
  • 又多跑了很多次,稳定重现,有时候是OOM,有时候是解析过程中抛解析的异常,很明显这个解析器多线不安全
  • 至此,该问题已经基本定位,该解析模块比较复杂,没深入研究,因为我这里有十分成熟的解决方案
  • 替换调用该解析器的两处代码,重启,再压,问题解决.

感受

  • 刚开始被派到现场解决这个问题的时候,心里一直很忐忑,解决不了怎么办?因为之前给的dump文件没有分析出问题点,现场能提供的肯定也是这些文件.解决不了怎么跟客户交代呢…
  • 来到现场,问题能够重现,有戏!
  • 分析过程还是要根据经验,逐步排查问题点