記一次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。我是在發出文章的前一刻看了一眼代碼才忽然發現這個問題。結論是：必定要細心啊！