2025-02-17

最近一個J2EE產品在生產環境下出現瞭內存泄露,下面是我們的主要處理步驟:

1.  下載gc的log,發現最近一年來,原來內存一直正常,呈鋸齒型,就是內存多瞭會通過gc回收掉,又回到較低的水平;到9月份的時候開始,內存緩慢增長;這裡值得註意的事該產品從去年到9月份沒有做過代碼、配置等任何更改。

到11月份開始,內存迅速增長,連續運行一個星期以上就要OutofMemory;

幸好該產品隻需要支持24*6的服務,每周末重啟一下暫時還不影響服務。

2.  在內存比較大的時候,生成一個heap dump,打開來看什麼對象占內存最多,發現下面這個類的對象占瞭大量的內存

Java.awt.EventQueueItem

找到代碼裡面用到這個類的地方,發現有大概如下的代碼

這是一段和第三方通信的代碼,基本情況是第三方會不斷的發很多事件過來讓我們處理,當前的日志看是大約1s發送100個事件左右,每發送一個事件過來會會調用OnEventNotify函數,然後我們需要調用doProcess,這個是第三方提供的jar裡面一個接口,第三方的代碼會先在內部處理下,然後我們實現的一個OnProcess函數裡面真正做事件處理;

// 過程好像比較糾結,第三方是個外國公司,我們公司的這段代碼之前也是老外寫的,我也還沒搞明白為什麼通知和處理要分開,直接想辦法做成處理不就可以瞭麼?!

onEventNofity(***)
{

java.awt.EventQueue.invokeLater(new Runnable(){
public void run() {
doProcess();
}
});

}這段代碼肯定是有問題,這個invokelater裡面代碼看進去是用新生成的Runnable對象構造瞭一個java.awt.event.InvocationEvent對象,然後會放到系統有一個默認的java.awt.EventQueue實現對象裡面,然後讓一個java.awt. EventDispatchThread調度,然後一個一個執行這裡的run方法;

首先相當於每次一個事件過來的時候就生成一個Runnable對象,進而生成InvocationEvent對象,占用瞭大量的內存,

可糾結的是為啥以前沒問題?而且這個版本在我們開發服務器上跑瞭幾個月現在還一直正常;

中間經過各個環境下的測試、日志分析、對比,終於慢慢發現,從對日志的時間分析看,現在的事件處理速度,就是doProcess這裡太慢瞭,導致事件處理不過來,然後大量的Runnable和InvocationEvent對象堆積在java.awt.EventQueue裡面,導致瞭內存的泄露;

9月份之前的app日志已經沒有瞭,看不出來當時的事件是否有那麼多,

而開發環境下,由於開發環境連的數據源也是第三方的開發環境,收到的數據相比正式生產環境要少一些,另外一個第三方處理相關的時間參數配置和生產服務器不一樣,導致doProcess這裡的處理時間在開發環境下更快一些,從而可以使處理速度趕上收到事件的速度,不會有Runnable和InvocationEvent對象的堆積,也不會有內存泄露

這裡寫瞭一個測試代碼說明這個內存泄露的過程,剛剛我在自己機器上跑瞭一下的輸出是

Thu Dec 09 07:19:38 CST 2010 before memory:2031616

Thu Dec 09 07:19:38 CST 2010  after memory:3432448

Thu Dec 09 07:20:22 CST 2010 now system exit

可以看到,在這個過程中,有140MB的內存堆積瞭,由於在實際生產環境下事件不停的發送過來,裡面處理速度始終趕不上,導致內存慢慢堆積,最終OutOfMemory;

下面是具體代碼:

package com.hetaoblog.demo;
import java.util.Date;


public class MemoryLeakTest {

        public static int n = 1;
        static int count = 20000;
        /**
         * @param args
         */
        public static void main(String[] args) {
                // TODO Auto-generated method stub

        System.out.println(new Date() + " before memory:" + Runtime.getRuntime().totalMemory());

                for(int i = 0; i < count; ++i)
                {
                        java.awt.EventQueue.invokeLater(new Runnable(){

 

                                public void run() {

                                        try {
                                                Thread.currentThread().sleep(1);
                                        } catch (InterruptedException e) {
                                                // TODO Auto-generated catch block
                                                e.printStackTrace();
                                        }

                                        n++;

                                        if(n == count)
                                        {
                                                System.out.println(new Date() + " now system exit");
                                        }

                                }

                        });
                }

        System.out.println(new Date() +"  after memory:" + Runtime.getRuntime().totalMemory());

        }

}

——————————————————————————-
昨天講瞭內存泄露問題的原因其實就是在下面這段代碼中無緣無故的搞個java.awt.invokeLater(New Runnable()….,
當然,作者本來的用意是好的,其實就是把收到事件和處理事件做異步化處理,本來的目的也是提高性能裡的情況是按照第三方的API,OnEventNotify()需要盡快返回,否則會堵住後面發過來的事件;

onEventNofity(***)
{

java.awt.EventQueue.invokeLater(new Runnable(){

                                public void run() {
doProcess();
}
                                });

}這段代碼的主要兩個問題:
1. java.awt.invokeLater裡面每次會新生成一個java.awt.event.InvocationEvent對象;
2.這裡的Runnable的匿名類,其實本來完全可以單獨定義的,現在這個寫法,相當於每次一個事件過來都new出一個Runnable的匿名類來。。。白白浪費瞭大量內存

導致內存泄露的情況就是事件現在較多,doProcess占用時間太長,導致java.awt.event.InvocationEvent對象大量堆積;
所以,解決思路其實比較明確,
1. 要麼提高處理速度使得事件不堆積,
2. 要麼改成其他異步化的方式,避免每次生成java.awt.event.InvocationEvent對象

在開發環境下連接到對方QA環境,使得數據量保持一致,重現瞭內存泄露問題後,經過分析調試測試,下面幾種方案都在開發環境下運行良好,內存保持穩定,gc日志和heapdump都很正常,解決瞭內存泄露問題:
1. 修改瞭兩個第三方API相關的配置參數,使得doProcess這裡處理速度提高瞭很多,於是即使在現在的事件數量下,仍然可以避免事件堆積;
2. 由於事件處理是該模塊的核心,而且凡是程序運行的時候必然會有事件不停的發送過來,所以,修改代碼如下
onEventNofity(***)
{
//這裡改成啥事也不做
}
然後程序起來的時候開一個線程不停的去做doProcess的事情;
由於這裡onEventNotify僅僅是起個通知的作用,真正的事件是放在內部的另外一個隊列裡,所以這樣做是可以的;如果有參數依賴,那可以在這個onEventNotify調用其他線程池的方式去做
—————————————————————————————-
之前寫瞭兩篇實戰java內存泄露的話題文章(診斷和代碼分析,解決方案),轉載到水木時,引起瞭一些討論,這裡對一些問題做一些說明;

1. 下面的觀點是我最贊同的,對岸那老外似乎GUI寫的太多瞭,沒事在這裡直接寫瞭這行代碼,java.awt.EventQueue.invokeLater(new Runnable():
Kobe2000:
非GUI程序怎麼能用invokexxx來異步執行呢,這個本來就有問題
icespace (蟈蟈):
服務器端的程序為毛要把doprocess放到awt的線程裡頭去?
這裡頭沒GUI啥事阿
這麼做結果可能是load一堆awt的類和迫使 系統調用一堆沒用的GUI事件在線程裡

這個應該一堆或者一個worker thread從queue裡取啊
用不著new 一堆runnable出來不吧

核桃博客說明:
下面是JDK中java.awt.EventQueue.invokeLater的源代碼

    public static void invokeLater(Runnable runnable) {
        Toolkit.getEventQueue().postEvent(
            new InvocationEvent(Toolkit.getDefaultToolkit(), runnable));
    }這裡可以看到,每調用一次,除瞭外面自己的new Runnable對象以外,裡面還會new 一個InvocationEvent對象,所以一來這裡浪費瞭大量內存和CPU時間,不停的new出東西來;
而來的確正確的做法應該是搞個後臺線程或者線程池來處理這些事件;

2. 這種情況究竟算不算內存泄露

這個問題其實很難嚴格界定,基本我理解是內存會保持一直增長的情況,那就是內存泄露瞭;
在這裡由於內存問題是和處理速度相關的,可以理解成是性能問題引發內存問題,假設後面事件急劇減少保持一定時間的話有可能會處理完,內存會恢復。
但是就現實情況就是事件保持穩定發送,內存被放到queue裡面後就慢慢增長瞭;當然這和傳統書上說的放進去以後由於邏輯錯誤再也釋放不掉的情況還是有所區別。

3. 有同學提出將事件持久化到數據庫然後再慢慢處理的方式
這個在我看來是完全不可行的,主要原因:
a. 通常這樣大量事件不停發送過來的系統需要盡快處理好這些事件,否則業務上就有問題瞭;要不然的話沒必要不停發送過來;這個系統就屬於這樣的情況;
先保存到數據庫然後出來慢慢處理時間上就延時好多瞭;
b. 無緣無故增加瞭數據庫的大量負載;在第一篇裡面說瞭,目前的數據量大概是1s有100個事件,就這樣不停的保持每秒做100個insert到數據庫,然後再從數據庫讀出這些事件來處理,對數據庫的負載增加太大;
c. 另外,雖然沒實際驗證過,不過我謹慎懷疑保存這個,就是按照1s100個事件,就是平均10ms一個事件。就我項目實際經驗,10ms做一個insert,差不多一次磁盤IO操作的時間,實際在Oracle 10g下跑差不多也就這個速度;碰上數據庫壓力大的時候10ms還搞不定;而且事件也不是完全均勻的,有高峰和低峰,碰上高峰的時候的話,保存到數據庫這個地方,又會成為瓶頸。

4.在解決方案裡面寫瞭兩個做法
a. 要麼提高處理速度使得事件不堆積,
b. 要麼改成其他異步化的方式,避免每次生成java.awt.event.InvocationEvent對象
下面是piggestbaby的回復:

1. 要麼提高處理速度使得事件不堆積,
2. 要麼改成其他異步化的方式,避免每次生成java.awt.event.InvocationEvent對象

1. 是正確的方向
2. 你確定不是由於 1 的改進而掩蓋的吧

如果在 僅對 1 進行瞭改進,還是出現 2 的情況
那麼原因可能有兩個
a. awt event dispather 處理效率很低,比直接串行處理數據效率低很多
b. InvocationEvent 對象比你們系統內部的隊列表示占用內存過大, new效率低

這裡1和2是分開兩種策略測試的:)所以不會存在1和2互相掩蓋的情況;
其實隻要處理能處理過來,經測試,仍然用java.awt.EventQueue.invokelater這樣錯誤的方式也還是不會堆積起來,不會有內存泄露
—————————————————————–
在實戰java內存泄露問 題2-解決方案 裡面說瞭,主要的一個解決思路是提高事件處理的速度,有一個情況是同一個版本的代碼在我們的DEV和QA/UAT/PROD的處理速度始終不一致,即使把所有相關的配置(主要是數據源)都配成一樣的,還是有較大區別;

然後看到DEV是Linux 2.6的,其他環境是Linux 2.4的;這是一個較大的差異,但是具體這個2.4和2.6對我們JAVA代碼的區別,一開始並不明白;後來才具體跟蹤發現:

wait(5)這行代碼在Linux 2.4和Linux 2.6下面會有很大的性能差異;

//當然根據分析這個情況其實是可以跳過的。。

在某一步,可能會執行到如下代碼,就是在一定情況下會等待


synchronized(o)

{

try {

o.wait(5);

} catch (InterruptedException e) {

// TODO Auto-generated catch block

e.printStackTrace();

}

}按照JDK的說明,這行代碼的意思是,如果有其他線程調用這個對象的notify()或者是notifyall()方法,那麼wait(5)結束;如果沒有被Notify()或者notifyall()的話,那麼超時後結束,這裡的話就是5ms後結束;

2. 然而實測發現,在Linux 2.4和Linux 2.6上,這段代碼會產生較大的性能差異;

測試方法,運行下面的WaitTimeTest代碼500次,然後用腳本統計平均時間

package com.hetaoblog.demo;

public class WaitTimeTest {

        /**
         * @param args
         */
        public static void main(String[] args) {
                // TODO Auto-generated method stub

                for(int i = 0; i < 100; ++i)
                {
                long t1 = System.currentTimeMillis();

                WaitTimeTest o = new WaitTimeTest();

                synchronized(o)
                {
                        try {
                                o.wait(5);
                        } catch (InterruptedException e) {
                                // TODO Auto-generated catch block
                                e.printStackTrace();
                        }
                }

                System.out.println("wait(5) used time: " + (System.currentTimeMillis() – t1));
                }

        }
}

測試環境:

JRE: J2RE 5.0 IBM J9 2.3 Linux x86
OS: Redhat As系列
CPU:x86系列的4個cpu

測試結果
  平均時間(ms)
2.4 14.8
2.6 6.1

就其原因,按我的理解是因為Linux 2.4和2.6內核調度算法從o(n)改到o(1),以及使用新的線程庫NPTL的改進,使得2.6在多CPU,多線程環境下性能提高很多
http://www.ibm.com/developerworks/cn/linux/l-web26/index.html
另外,我在自己的T60,winxp上測瞭下sun的jdk,這個wait(5)基本需要16ms的時間;
這說明這3個環境下,IBM的JDK在2.6上的多線程調度的性能完勝瞭:)

作者“ERDP技術架構”

發佈留言

發佈留言必須填寫的電子郵件地址不會公開。 必填欄位標示為 *