放翁(文初)的一畝三分地

            BlogJava :: 首頁 :: 新隨筆 :: 聯(lián)系 :: 聚合  :: 管理 ::
            210 隨筆 :: 1 文章 :: 320 評論 :: 0 Trackbacks
          越是忙,雜七雜八的事情越多,最近正在優(yōu)化Memcache的客戶端代碼,這時候SIP突然出現(xiàn)OOM的問題(Out of Memory),作開發(fā)最頭痛就是這種問題,壓力測試都作過,早期的幾個版本都沒有出現(xiàn)這樣的問題,因此懷疑可能是最近一次發(fā)布修改引起的。借助JProfiler在測試環(huán)境搭了一套系統(tǒng),開始做壓力測試,來分析Memory到底流到了哪里去了。

          問題一:連接池泄漏

                 看到這個問題,我想很多人都說,都什么年代了,使用開源的現(xiàn)成連接池,怎么還會有這樣的問題,又不是那些使用jdbc的年代了。那來看看現(xiàn)象吧。

          場景:測試部用loadRunner往死里壓,發(fā)現(xiàn)很多業(yè)務(wù)對象不斷增長,但是按照業(yè)務(wù)場景來說,這些業(yè)務(wù)對象處理以后就自動釋放了。(在本地的開發(fā)環(huán)境驗證了是會自動釋放的)

          JProfiler截圖:

                 上圖中可以看到有很多業(yè)務(wù)對象已經(jīng)累積占用了不少內(nèi)存,在讓測試部同學(xué)停掉壓力測試以后,等待了一會兒,然后用JProfiler主動發(fā)起垃圾回收,也看到了Jboss后臺有GC回收的記錄輸出以后,發(fā)現(xiàn)這些對象依然存在,也就是說這些對象成為了Memory泄漏的誘因之一。但是就如我所說的,在本地測試以及白盒測試來看,這些對象在一次請求以后,處理完畢一定會被釋放,沒有被其他MapReference,然后通過JProfiler看了看這些對象的Allocation Call Tree,就是我們處理請求的Servlet作為源頭的,但為什么Servlet沒有被清理掉呢?接著來看看后面二張圖

                 既然知道對象存在并且被Hold了,那么就去看看線程運行的狀況,這一看發(fā)現(xiàn)有很多線程都處于Wait的狀態(tài)(其實在serverdump也可以看到),這張圖上就可以看到,我選擇了其中一個wait的線程它處于等待狀態(tài)的原因就是在ibatisThrottleincrement的時候處于等待狀態(tài),看了看ibatis的代碼,這部分代碼其實是ibatis連接池的一段代碼,在連接池被占滿以后,處于等待釋放的狀態(tài),也就是說程序把連接池耗盡了。

                 為了驗證是否是耗盡了,讓DBA老大光輝給我看了看MySql(這部分當(dāng)天的日志數(shù)據(jù)都保存在MySql中)的連接情況,發(fā)現(xiàn)只有8個連接,看來不是真的耗盡,應(yīng)該是連接池泄露了。光輝告訴我,這八個連接都在做同一個查詢,就是統(tǒng)計某一個API的訪問記錄次數(shù)和流量。在當(dāng)前的業(yè)務(wù)流程中對于MySql主要做了兩類操作:

                 1.訪問控制計數(shù)器創(chuàng)建的統(tǒng)計查詢。

          由于要對Open API訪問控制,采用了Memcache計數(shù)器方式來實現(xiàn)。當(dāng)發(fā)現(xiàn)此類API沒有創(chuàng)建過計數(shù)器,那么就分析MySql中的數(shù)據(jù),創(chuàng)建計數(shù)器,后續(xù)的訪問記錄除了插入數(shù)據(jù)庫以外還需要累加計數(shù)器,這樣訪問控制可以高效使用集中式計數(shù)器而不需要查詢數(shù)據(jù)庫。

          2.日志批量異步寫入。

          對于Open API的記錄采用了線程池中每一個線程維護一個內(nèi)存分頁,當(dāng)頁滿或者到了刷新間隔時,一次性批量寫入數(shù)據(jù)庫,緩解數(shù)據(jù)庫寫入壓力,這里采用了事務(wù)來批量提交。

                 對于第一種操作,由于設(shè)計中MySql就只會保留當(dāng)天的數(shù)據(jù)量,因此只有系統(tǒng)啟動的時候做一次統(tǒng)計,對于數(shù)據(jù)庫壓力和Sql執(zhí)行來說應(yīng)該沒有太大的壓力,但是由于壓力測試是從昨天下午就開始做的,里面的數(shù)據(jù)已經(jīng)有上千萬,因此這次重新啟動開始做壓力測試,導(dǎo)致了這個創(chuàng)建計數(shù)器的Sql執(zhí)行很慢。同時日志的批量寫入采用的是事務(wù)方式來提交,對于MySql其實自己還不是很深入,但是感覺上來說,問題應(yīng)該出現(xiàn)在這里,由于查詢的緩慢在加上事務(wù)批量的提交,可能會造成事務(wù)失敗,同時沒有正確的將釋放資源的信號傳遞給ibatis,導(dǎo)致了看起來的連接資源耗盡。

                 我將數(shù)據(jù)庫中的記錄全部刪除,然后重新啟動,開始壓力測試,問題不存在了,對象都及時得到回收。后續(xù)還會去跟進這個問題,在ibatis早期版本,同樣是這個類出現(xiàn)了死鎖的問題,后來升級得到了解決,但是也看到很多國外的朋友說道2.22.3其實還是有死鎖的問題,不過我個人覺得可能還是和數(shù)據(jù)庫也有一定關(guān)系。

          疑問:

                 這個問題的背后我還有一點疑問,對于我們來說,如果一個普通的http請求,當(dāng)超時以后肯定就會自動中斷,但是在這個場景中,我足足等了1個小時還是沒有釋放,也就是說客戶端其實已經(jīng)斷開了,但是JBoss好像并不會釋放這些處理請求的事務(wù),導(dǎo)致資源被卡。

          問題二:LinkedBlockingQueue惹禍

                 自從Jdk1.5以后concurrent包為大家提供了很多便利高效的開發(fā)新模式,我在不少地方用到了LinkedBlockingQueue,作為消費者和生產(chǎn)者之間的數(shù)據(jù)通道,消費者們等待在LinkedBlockingQueue門口守候生產(chǎn)者提供數(shù)據(jù),獲取數(shù)據(jù)后就開始并行處理。這里我會采用queue.poll(100,TimeUnit.MILLISECONDS)這種方式來半阻塞的獲取數(shù)據(jù)。其實在昨天已經(jīng)聽說LinkedBlockingQueue可能存在著內(nèi)存泄露的問題,看了看很多網(wǎng)上的人也都提到了這個問題,在1.5種沒有得到解決,在1.6中會去fix這個問題,但是沒有證據(jù),也不好亂加斷定。在問題一搞好以后,然后繼續(xù)查找潛在bug,這時候不經(jīng)意的發(fā)現(xiàn)有一個對象隨著時間的推移始終在增加,但是由于單個對象占的內(nèi)存不大,因此沒有很明顯的體現(xiàn)出來,但是對象實例的增加卻是很明顯的,看看下面兩張圖:

                

          這兩張圖的間隔時間2小時左右,可以發(fā)現(xiàn)這個對象的instance已經(jīng)有了很大的增長,同時內(nèi)存也吃了不少,看了看創(chuàng)建這個對象的Tree,發(fā)現(xiàn)就是poll這個方法,也就是我線程池中線程周期性掃描的結(jié)果。這期間沒有任何訪問,僅僅就是放著不動,就有如此大量的增長。我嘗試將poll(100,TimeUnit.MILLISECONDS)換成poll()全阻塞方式,對象增長依舊。因此可以看出來服務(wù)器的Memory Leak很大程度上由這部分引起,早先沒有發(fā)現(xiàn),因為是SIP上線不久,沒有太多用戶,而這陣子用戶越來越多,加上API中的更新類請求比較吃內(nèi)存,就容易發(fā)現(xiàn)此類問題。

                 那么是否1.6就解決了這個問題呢,開始使用機器上1.6_01的版本,發(fā)現(xiàn)問題依舊,去sun下載了最新的1.6_07,發(fā)現(xiàn)的卻會回收,但是回收和增長都存在,具體數(shù)據(jù)描述舉例如下:

          1.       1000 instance   31k

          2.       200 instance    6k (回收了一部分)

          3.       1500 instance   46k(發(fā)現(xiàn)增長的比以前還多)

          4.       300 instance    9k (回收了一部分)

          5.       2000 instance   62k (發(fā)現(xiàn)增長的比以前還多)

          也就是說,回收時有發(fā)生,但是總體趨勢還是在上升,這個真的還需要好好測試,有興趣的同學(xué)也可以試驗一下我的測試方式,就僅僅只需要使用一個LinkedBlockingQueue,然后定時的去pool1.5絕對增長的不小。

                 對于這個問題,我只能再去驗證,如果發(fā)現(xiàn)真的暫時不可避免,那么只有考慮替代方案了。

          這是今天作了Memory Leak的一些分享,希望也能給其他遇到或者將會遇到問題的同學(xué)一個分享,說一句,如果有條件的話用JProfiler去分析性能絕對是不錯的,沒有條件么就dump,gc輸出來查找問題。
             剛剛作了測試現(xiàn)在的場景可以用take來替換poll,原來是看中了poll的timeout方式,take完全沒有問題,看來如果要在1.5版本用,還是老老實實用take。

          posted on 2008-09-18 22:14 岑文初 閱讀(3935) 評論(4)  編輯  收藏

          評論

          # re: Memory Leak分析分享 2008-09-19 09:15 dennis
          LinkedBlockingQueue的這個問題在jdk1.6.2以上版本已經(jīng)解決了,用jprofiler觀察下,盡管一直在增加,但是執(zhí)行run gabage collector in profiled application的時候會立即減下來。  回復(fù)  更多評論
            

          # re: Memory Leak分析分享 2008-09-19 09:20 dennis
          另外poll()不是全阻塞吧,poll()如果隊列為空會返回null,take()才是全阻塞,建議用take()來做替代  回復(fù)  更多評論
            

          # re: Memory Leak分析分享 2008-09-19 09:46 文初
          對的,樓上說的是,這里寫錯了,以前用poll就是為了timeout來做半阻塞。對于jdk1.6是否解決了,我還需要在看看,在我寫的里面提到了的確看到有回收,但不知道為什么會始終在增加。沒有請求的時候也在增長,這就有點讓人擔(dān)心了。現(xiàn)在用take試試看。  回復(fù)  更多評論
            

          # re: Memory Leak分析分享 2008-09-19 11:33 隔葉黃鶯
          拜讀過,很有意義,總結(jié)起來就是兩點
          1. iBatis 的Throttle作increment 有可能造成阻塞線程
          2. 1.6.2 jdk 以前的 LinkedBlockingQueue.poll() 方法會帶來內(nèi)存溢出,用全阻塞的 take() 方法就能避免,或者升級 jdk 到 1.6.2 版。  回復(fù)  更多評論
            


          只有注冊用戶登錄后才能發(fā)表評論。


          網(wǎng)站導(dǎo)航:
           
          主站蜘蛛池模板: 金平| 烟台市| 尉氏县| 武穴市| 杭锦旗| 大竹县| 南川市| 蓬安县| 喜德县| 达孜县| 雷山县| 仁化县| 厦门市| 亳州市| 苏州市| 北辰区| 永清县| 吴堡县| 宾阳县| 通榆县| 鄂伦春自治旗| 都江堰市| 湘阴县| 赞皇县| 汝城县| 庄河市| 淅川县| 军事| 麻城市| 尼玛县| 东辽县| 汉川市| 元谋县| 疏附县| 桓仁| 安平县| 晋中市| 商都县| 乌拉特前旗| 景东| 家居|