SIP5.0以后服務(wù)的請(qǐng)求量爆發(fā)性增長(zhǎng)，因此也暴露了原來(lái)沒(méi)有暴露出來(lái)的問(wèn)題。由于過(guò)去一般一個(gè)新版本發(fā)布周期在一個(gè)月左右，因此如果是小的內(nèi)存泄露，在一個(gè)月之內(nèi)重新發(fā)布以后也就看不出任何問(wèn)題。
因此這陣子除了優(yōu)化Memcache客戶端和SIP框架邏輯以外其他依賴部分以外，對(duì)于內(nèi)存泄露的壓力測(cè)試也開(kāi)始實(shí)實(shí)在在的做起來(lái)。經(jīng)過(guò)這次問(wèn)題的定位和解決以后，大致覺(jué)得對(duì)于一個(gè)大用戶量應(yīng)用要放心的話，那么需要做這么幾步。
1. 在GC輸出的環(huán)境下，大壓力下做多天的測(cè)試。（可以在 JAVA_OPTS增加-verbose:gc -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError）
2. 檢查GC輸出日志來(lái)判斷是否有內(nèi)存泄露。（這部分后面有詳細(xì)的實(shí)例說(shuō)明）
3. 如果出現(xiàn)內(nèi)存泄露問(wèn)題，則使用jprofiler等工具來(lái)排查內(nèi)存泄露點(diǎn)（之所以不一開(kāi)始使用，因?yàn)?/span>jprofiler等工具對(duì)于壓力測(cè)試有影響，使得大壓力無(wú)法上去，也使問(wèn)題不那么容易暴露）
4. 解決問(wèn)題，并在重復(fù)2步驟。
這里對(duì)SIP在jdk1.5和jdk1.6下做壓力測(cè)試的GC 日志來(lái)做一個(gè)實(shí)際的分析對(duì)比，通過(guò)對(duì)比來(lái)大致描述一下如何根據(jù)輸出情況能夠了解應(yīng)用是否存在內(nèi)存泄露問(wèn)題。（這里的內(nèi)存泄露問(wèn)題就是在以前blog寫(xiě)過(guò)的jdk的concurrent包內(nèi)LinkedBlockingQueue的poll方法存在比較嚴(yán)重的內(nèi)存泄露，調(diào)用頻率越高，內(nèi)存泄露的越厲害）
兩次壓力測(cè)試都差不多都是兩天，測(cè)試方案如下：
開(kāi)始50個(gè)并發(fā)，每個(gè)并發(fā)每次請(qǐng)求完畢后休息0.1秒，10分鐘后增長(zhǎng)50個(gè)并發(fā)，按此規(guī)律增長(zhǎng)到500并發(fā)。
舊版本SIP是在JDK1.5環(huán)境下完成的壓力測(cè)試，
新版本SIP的JDK版本是1.6，
壓力機(jī)和以前一樣，是10.2.226.40，DELL1950，8CPU，8G內(nèi)存。
壓力機(jī)模擬發(fā)出對(duì)一個(gè)需要簽名的API不斷的調(diào)用請(qǐng)求。
看看兩個(gè)Log的具體內(nèi)容（內(nèi)容很多截取部分做分析）
先說(shuō)一下日志輸出的結(jié)構(gòu)：(1.6和1.5略微有一些不同，只是1.6對(duì)于時(shí)間統(tǒng)計(jì)更加細(xì)致)
[GC [<collector>: <starting occupancy1> -> <ending occupancy1>, <pause time1> secs] <starting occupancy3> -> <ending occupancy3>, <pause time3> secs]
<collector>GC收集器的名稱
<starting occupancy1> 新生代在GC前占用的內(nèi)存
<ending occupancy1> 新生代在GC后占用的內(nèi)存
<pause time1> 新生代局部收集時(shí)jvm暫停處理的時(shí)間
<starting occupancy3> JVM Heap 在GC前占用的內(nèi)存
<ending occupancy3> JVM Heap 在GC后占用的內(nèi)存
<pause time3> GC過(guò)程中jvm暫停處理的總時(shí)間
Jdk1.5 log：
啟動(dòng)時(shí)GC輸出：
[GC [DefNew: 209792K->4417K(235968K), 0.0201630 secs] 246722K->41347K(498112K), 0.0204050 secs]
[GC [DefNew: 214209K->4381K(235968K), 0.0139200 secs] 251139K->41312K(498112K), 0.0141190 secs]
一句輸出：
新生代回收前209792K，回收后4417K，回收數(shù)量205375K，Heap總量回收前246722K回收后41347K，回收總量205375K。這就表示100%的收回，沒(méi)有任何新生代的對(duì)象被提升到中生代或者永久區(qū)（名字說(shuō)的不一定準(zhǔn)確，只是表達(dá)意思）。
第二句輸出：
按照分析也就只是有1K內(nèi)容被提升到中生代。
運(yùn)行一段時(shí)間后：
[GC [DefNew: 210686K->979K(235968K), 0.0257140 secs] 278070K->68379K(498244K), 0.0261820 secs]
[GC [DefNew: 210771K->1129K(235968K), 0.0275160 secs] 278171K->68544K(498244K), 0.0280050 secs]
第一句輸出：
新生代回收前210686K，回收后979K，回收數(shù)量209707K，Heap總量回收前278070K回收后68379K，回收總量209691K。這就表示有16k沒(méi)有被回收。
第二句輸出：
新生代回收前210771K，回收后1129K，回收數(shù)量209642K，Heap總量回收前278171K回收后68544K，回收總量209627K。這就表示有15k沒(méi)有被回收。
比較一下啟動(dòng)時(shí)與現(xiàn)在的新生代占用內(nèi)存情況和Heap使用情況發(fā)現(xiàn)Heap的使用增長(zhǎng)很明顯，新生代沒(méi)有增長(zhǎng)，而Heap使用總量增長(zhǎng)了27M，這就表明可能存在內(nèi)存泄露，雖然每一次泄露的字節(jié)數(shù)很少，但是頻率很高，大部分泄露的對(duì)象都被升級(jí)到了中生代或者持久代。
又一段時(shí)間后：
[GC [DefNew: 211554K->1913K(235968K), 0.0461130 secs] 350102K->140481K(648160K), 0.0469790 secs]
[GC [DefNew: 211707K->2327K(235968K), 0.0546170 secs] 350275K->140921K(648160K), 0.0555070 secs]
第一句輸出：
新生代回收前211554K，回收后1913K，回收數(shù)量209641K，Heap總量回收前350102K回收后140481K，回收總量209621K。這就表示有20k沒(méi)有被回收。
分析到這里就可以看出每一次泄露的內(nèi)存只有10幾K，但是在大壓力長(zhǎng)時(shí)間的測(cè)試下，內(nèi)存泄露還是很明顯的，此時(shí)Heap已經(jīng)增長(zhǎng)到了140M，較啟動(dòng)時(shí)已經(jīng)增長(zhǎng)了100M。同時(shí)GC占用的時(shí)間越來(lái)越長(zhǎng)。
后續(xù)的現(xiàn)象：
后續(xù)觀察日志會(huì)發(fā)現(xiàn)，Full GC的頻率越來(lái)越高，收集所花費(fèi)時(shí)間也是越來(lái)越長(zhǎng)。（Full GC定期會(huì)執(zhí)行，同時(shí)局部回收不能滿足分配需求的情況下也會(huì)執(zhí)行）。
[Full GC [Tenured: 786431K->786431K(786432K), 3.4882390 secs] 1022399K->1022399K(1022400K), [Perm : 36711K->36711K(98304K)], 3.4887920 secs]
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid7720.hprof ...
出現(xiàn)這個(gè)語(yǔ)句表示內(nèi)存真的被消耗完了。
Jdk1.6 log：
啟動(dòng)時(shí)GC的輸出：
[GC [PSYoungGen: 221697K->31960K(229376K)] 225788K->36051K(491520K), 0.0521830 secs] [Times: user=0.26 sys=0.05, real=0.05 secs]
[GC [PSYoungGen: 228568K->32752K(229376K)] 232659K->37036K(491520K), 0.0408620 secs] [Times: user=0.21 sys=0.02, real=0.04 secs]
第一句輸出：
新生代回收前221697K，回收后31960K，回收數(shù)量189737K，Heap總量回收前225788K回收后36051K，回收總量189737K。100%被回收。
運(yùn)行一段時(shí)間后輸出：
[GC [PSYoungGen: 258944K->2536K(259328K)] 853863K->598135K(997888K), 0.0471620 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]
[GC [PSYoungGen: 259048K->2624K(259328K)] 854647K->598907K(997888K), 0.0462980 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]
第一句輸出：
新生代回收前258944K，回收后2536K，回收數(shù)量256408K，Heap總量回收前853863K回收后598135K，回收總量255728K。680K沒(méi)有被回收，但這并不意味著就會(huì)產(chǎn)生內(nèi)存泄露。同時(shí)可以看出GC回收時(shí)間并沒(méi)有增加。
在運(yùn)行一段時(shí)間后輸出：
[GC [PSYoungGen: 258904K->2488K(259264K)] 969663K->713923K(1045696K), 0.0485140 secs] [Times: user=0.16 sys=0.01, real=0.04 secs]
[GC [PSYoungGen: 258872K->2448K(259328K)] 970307K->714563K(1045760K), 0.0473770 secs] [Times: user=0.16 sys=0.01, real=0.05 secs]
第一句輸出：
新生代回收前258904K，回收后2488K，回收數(shù)量256416K，Heap總量回收前969663K回收后713923K，回收總量255740K。676K沒(méi)有被回收，同時(shí)總的Heap也有所增加。
此時(shí)看起來(lái)好像和1.5的狀況一樣。但是查看了一下Full GC的執(zhí)行還是400-500次GC執(zhí)行一次，因此繼續(xù)觀察。
運(yùn)行一天多以后輸出：
[GC [PSYoungGen: 257016K->3304K(257984K)] 1019358K->766310K(1044416K), 0.0567120 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]
[GC [PSYoungGen: 257128K->2920K(258112K)] 1020134K->766622K(1044544K), 0.0549570 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
可以發(fā)現(xiàn)Heap增長(zhǎng)趨緩。
運(yùn)行兩天以后輸出：
[GC [PSYoungGen: 256936K->3584K(257792K)] 859561K->606969K(1044224K), 0.0565910 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]
[GC [PSYoungGen: 256960K->3368K(257728K)] 860345K->607445K(1044160K), 0.0553780 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]
發(fā)現(xiàn)Heap反而減少了，此時(shí)可以對(duì)內(nèi)存泄露問(wèn)題作初步排除了。（其實(shí)在jdk1.6環(huán)境下用jprofiler來(lái)觀察，對(duì)于concurrent那個(gè)內(nèi)存泄露點(diǎn)的跟蹤發(fā)現(xiàn)，內(nèi)存的確還是會(huì)不斷增長(zhǎng)的，不過(guò)在一段時(shí)間后還是有回收，因此也就可以部分解釋前面出現(xiàn)的情況）
總結(jié)：
對(duì)于GC輸出的觀察需要分兩個(gè)維度來(lái)看。一個(gè)是縱向比較，也就是一次回收對(duì)于內(nèi)存變化的觀察。一個(gè)是橫向比較，對(duì)于長(zhǎng)時(shí)間內(nèi)存分配占用情況的比較，這部分比較需要較長(zhǎng)時(shí)間的觀察，不能僅僅憑短時(shí)間的幾個(gè)抽樣比較，因?yàn)閷?duì)于抽樣來(lái)說(shuō)，Full GC前后的區(qū)別，運(yùn)行時(shí)長(zhǎng)的區(qū)別，資源瞬時(shí)占用的區(qū)別都會(huì)影響判斷。同時(shí)要結(jié)合Full GC發(fā)生的時(shí)間周期，每一次GC收集所耗費(fèi)的時(shí)間作為輔助判斷標(biāo)準(zhǔn)。
順便說(shuō)一下，Heap的 YoungGen,OldGen,PermGen的設(shè)置也是需要注意的，并不是越大越好，越大執(zhí)行收集的時(shí)間越久，但是可能執(zhí)行Full GC的頻率會(huì)比較低，因此需要權(quán)衡。這些仔細(xì)的去了解一下GC的基礎(chǔ)設(shè)計(jì)思想會(huì)更有幫助，不過(guò)一般用默認(rèn)的也不錯(cuò)。還有就是可以配置一些特殊的GC，并行，同步等等，充分利用多CPU的資源。
對(duì)于GC的優(yōu)化可以通過(guò)現(xiàn)在很多圖形工具來(lái)做，也可以類似于我這樣采用最原始的分析方式，好處就是任何時(shí)間任何地點(diǎn)只要知道原理就可以分析無(wú)需借助外部工具。原始的總是最好的^_^。