记一次OOM的排查过程

在最近公司产品的一次release中，咱们遇到了一个Java OOM的问题，追查了几个小时才解决问题，并且过后发现形成问题的缘由很简单，但追查的过程我认为值得记录一下。

1. 现象

咱们的应用是跑在64位的Red Hat Enterprise Linux上的，Heap配置为1G。在那天release跑BAT测试用例的时候，发现不按期地系统会开始不工做，一查后台的日志，能发现很多OutOfMemoryError的异常，以下：

java.lang.OutOfMemoryError java.util.zip.ZipFile.open(Native Method) java.util.zip.ZipFile.(ZipFile.java:112) java.util.jar.JarFile.(JarFile.java:127) java.util.jar.JarFile.(JarFile.java:92) org.apache.catalina.loader.WebappClassLoader.openJARs(WebappClassLoader.java:1544) org.apache.catalina.loader.WebappClassLoader.findResourceInternal(WebappClassLoader.java:1763) ...

异常是在ClassLoader打开jar文件以作类加载时抛出的，看堆栈跟踪发现与具体加载的类无关，是随机出现的。Google了一番，发现 ZipFile类在打开文件的时候用的是本地内存而不是Java堆（因此OOM后面没有说是heap space）。我用pmap来看了一下进程的内存占用信息，发现居然能占用到3G多！Heap Space才1G，内存却占用有3G，并且咱们没有用DirectBuffer之类的须要占用堆外内存的类，因此咱们推测应该是有线程泄漏的状况：每一个 Java线程都须要堆栈空间，而堆栈空间的确是Java Heap以外的。咱们没有改-Xss参数，即线程堆栈大小为默认的1M，因此内存占用有3G，说明系统中存在这大量的线程（几千个）。

不过这里还有一件事有些蹊跷，为何内存占用到3G多就抛OutOfMemory了？毕竟咱们用的是64位OS，地址空间应该超级庞大才对。结果咱们发现……

2. 32-bit JVM on 64-bit Linux

在这个OOM的问题困扰了咱们好半天，致使测试进行不下去的时候我才开始往这个方向想——毕竟谁能想到会发生这么低级的失误，在64位的OS上运行32位的JVM呢？

 开始怀疑这个之后，用file命令查了一下系统JRE里的java可执行文件，结果是：

[root@X64_213 bin]# file java java: ELF 32-bit LSB executable, Intel 80386, version 1 (SYSV), for GNU/Linux 2.2.5, dynamically linked (uses shared libs), for GNU/Linux 2.2.5, stripped

 果真和本身怀疑的同样。

而后咱们换成了64位的JRE，继续测试，但其实真正的问题还没解决，只是暂时被隐藏起来了而已。

3. 系统卡死

换成64位JRE之后咱们只测试了一会，新的问题就出现了，此次是系统卡死。其实这也在预料之中，只不过在忙于功能测试的时候暂时选择性无视了而已。

用pmap看了一下java进程的内存占用，好家伙，先是12G，接着有一次到了27G！！！系统彻底没有响应，ssh也彻底卡住了。此次咱们不得不认真追查问题了。

用ps -eLf看了一下，java进程居然有几万个线程！这下能够确定是系统中某个地方会大量建立线程了。但是比较郁闷的是jstack老会出问题，在dump 已经被JIT编译过的本地栈时，会抛出异常，致使彻底看不到线程在干什么，卡在什么地方。这时想起来一招，这招在Web系统里很好用：写一个jsp，里面 调用Thread.getAllStackTraces()这个方法来获取当前JVM里全部java线程的堆栈跟踪信息，而后输出到网页上。经过这个方法 得到的堆栈跟踪不会受JIT编译的影响，很适合作Trouble Shooting用。

因而咱们现写了一个这样的JSP页面，把它放到咱们的一个Web Context里面，重启了系统。以后再测试，重现问题后立刻访问这个JSP页面，果真找到了那些大量产生的线程：原来是java.util.Timer 所建立的TimerThread线程，并且它们全都阻塞在Object.wait()里了。

查了一下Timer类的源代码，有以下发现：

1. java.util.Timer类在构造方法里就会建立线程并启动它
2. 若是Timer中没有任务，TimerThread线程会阻塞在task queue的wait上

 因此能得出结论就是系统中有某个地方在大量建立Timer

4. 罪魁祸首

咱们在代码里寻找全部引用了java.util.Timer的地方，把代码仔细阅读了几遍，没有发现问题。这些Timer都是静态的或者在单例中，没有大量建立的可能性。咱们不得不把目光放到第三方包里。

咱们这个项目由于用到了Sip协议，因此引用了一个叫jain-sip-ri的第三方Sip协议栈实现。它是此项目中新增的功能所引用的库，在早先的产品里是不存在的，而咱们以前也从未出现过相似的问题，因此就把怀疑的目光投向了它：jain-sip-ri

咱们写了一段测试代码，直接调用咱们代码里使用了jain-sip-ri的部分，果真重现了大量建立线程的问题，因而用btrace跟踪了一下全部调用了java.util.Timer构造方法的地方，脚本以下：

@BTrace public class NewTimer {     @OnMethod( clazz="java.util.Timer", method="" )     public static void onnew() {          println("----------------------------------------");          jstack(); } }

运行后的结果以下：

java.util.Timer.(Timer.java:106)     gov.nist.javax.sip.stack.BlockingQueueDispatchAuditor.start(BlockingQueueDispatchAuditor.java:25)     gov.nist.javax.sip.stack.UDPMessageProcessor.(UDPMessageProcessor.java:134)     gov.nist.javax.sip.stack.OIOMessageProcessorFactory.createMessageProcessor(OIOMessageProcessorFactory.java:46) gov.nist.javax.sip.stack.SIPTransactionStack.createMessageProcessor(SIPTransactionStack.java:2372)     gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1371)     gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1537)     com.workssys.share.oma.SipLayer.createPrivider(SipLayer.java:290)

根源就在这个BlockingQueueDispatchAuditor里了，因而下载了一份源代码，找到了相应的方法，以下：

public void start(int interval) {     if(started) stop();     started = true;     timer = new Timer();     timer.scheduleAtFixedRate(this, interval, interval);  }

每次启动的时候BlockingQueueDispatchAuditor都会建立一个Timer。继续顺着stack trace定位上层的代码，有以下发现：

1. 每次createListeningPoint调用，都会致使一个新的MessageProcessor被建立
2. createListeningPoint后续的动做若是失败了，不会销毁建立出来的MessageProcessor（至少没有cancel Timer）

进一步查看咱们本身的代码，发现有一处循环调用createListeningPoint！原来绑定Sip端口的逻辑是从一个起始端口开始不断尝试 绑定，失败的话就让端口加1，直到成功为止。虽然这里可能会出现死循环，但一般是不该该出现几百上千个连续端口全都被占用的状况才对。分析到这，咱们同事 终于想起来一件事：原来他以前为了测试，把绑定IP改为了一个硬编码的值，后来不当心把这个改动commit了。测试Server的IP必然和他以前用的 IP不同，不管用什么端口都必然绑定不上，因此那段代码会无限循环，无限调用createListeningPoint，最后由于jain-sip里的 小漏洞而无限建立Timer对象和TimerThread线程，进而致使了这一连串离奇的现象。

5. 结论

我以为找这个问题的过程挺狗血的，惟一有些价值的我认为是如下几点：

1. 64位OS上运行的32位进程，地址空间只有4G，其实这个结论是显而易见的，但容易被忽略
2. Java Web系统里能够用一个小JSP页面来调用Thread.getAllStackTraces生成全部线程的状态，这是替代jstack的一个很不错的一招！
3. btrace是个好东西，仅仅是为了这个工具而将运行环境迁移到Java 6上都是很值得的！
4. 最好不要为测试去改被测试的代码，如这里提到的把IP改为硬编码的本机IP，更好的办法应该是提升代码的“可测试性”

6. 插曲

这篇文章写出来有两天了，但再最后发出来以前的一刻，发现以前的分析有错！下面是原始的错误分析：

我Download下来这个包的源代码，在里面搜索Timer，结果找到了一个叫DefaultSipTimer的类，正好就是 java.util.Timer的子类。接着搜索引用了这个类的地方，找到了一个叫SipStackImpl的类里的两处引用，一处是在构造函数里：

String defaultTimerName = configurationProperties.getProperty("gov.nist.javax.sip.TIMER_CLASS_NAME",DefaultSipTimer.class.getName());     try {         setTimer((SipTimer)Class.forName(defaultTimerName).newInstance());          getTimer().start(this, configurationProperties);         if (getThreadAuditor().isEnabled())         { // Start monitoring the timer thread             getTimer().schedule(new PingTimer(null), 0);         }     } catch (Exception e)     {         logger.logError("Bad configuration value for gov.nist.javax.sip.TIMER_CLASS_NAME", e); }

另外一处在一个叫reInitialize的方法：

if(!getTimer().isStarted())  {     String defaultTimerName = configurationProperties.getProperty("gov.nist.javax.sip.TIMER_CLASS_NAME",DefaultSipTimer.class.getName());     try     {         setTimer((SipTimer)Class.forName(defaultTimerName).newInstance());         getTimer().start(this, configurationProperties);         if (getThreadAuditor().isEnabled())         { // Start monitoring the timer thread                 getTimer().schedule(new PingTimer(null), 0);         }      } catch (Exception e)         {             logger.logError("Bad configuration value for gov.nist.javax.sip.TIMER_CLASS_NAME", e);      } }

仔细想一下就能发现这里有个严重的漏洞，若是Timer尚未被启动，就会在这里被从新建立，但同时原来的Timer没有被Cancel 掉，其实仍是存在的，对应的TimerThread线程也还在跑。因此只要由于某个缘由让reInitialize这个方法被不断调用，就会发生无限建立 线程的情况！

看一下上面的代码能发现，reInitialize里其实已经检查了SipTimer是否已经启动，只有未启动的时候才会从新建立Timer，而这 两处都有调用start，即这里不可能无限建立Timer。我是在发出文章的前一刻看了一眼代码才忽然发现这个问题。结论是：必定要细心啊！