CMS gc實(shí)踐調(diào)整(續(xù)2)
Posted on 2009-09-26 18:29 dennis 閱讀(2105) 評(píng)論(1) 編輯 收藏 所屬分類(lèi): java 本以為在上篇定稿的參數(shù)后應(yīng)該能有比較好的表現(xiàn),然后實(shí)際的表現(xiàn)大出我的意料,cms回收觸發(fā)非常頻繁,雖然每次都只是10-50毫秒,但是次數(shù)12個(gè)小時(shí)內(nèi)能達(dá)到180多次,這顯然不正常。通過(guò)gc日志和jstat可以看到,每次old區(qū)還在5%左右就開(kāi)始進(jìn)行CMS,此時(shí)的perm區(qū)也才30%,這兩個(gè)數(shù)字有浮動(dòng)并且CMS觸發(fā)的時(shí)間上也沒(méi)有規(guī)律,在測(cè)試環(huán)境和生產(chǎn)環(huán)境中都是如此。
那么最后是怎么解決的呢?其實(shí)沒(méi)有解決。我只是替換了一個(gè)參數(shù)就沒(méi)再發(fā)生這個(gè)現(xiàn)象,上文提到為了避免System.gc()調(diào)用引起的full gc,使用了jdk6引入的新參數(shù)-XX:+ExplicitGCInvokesConcurrent來(lái)讓System.gc()并發(fā)執(zhí)行,但是測(cè)試表明恰恰是這個(gè)參數(shù)引起了CMS的頻繁發(fā)生,去掉這個(gè)參數(shù)就沒(méi)有那個(gè)奇特的現(xiàn)象。重復(fù)檢查了代碼,并且再次查看了GC日志,沒(méi)有再發(fā)現(xiàn)有System.gc()的調(diào)用,我暫時(shí)將原因歸結(jié)于使用了ExplicitGCInvokesConcurrent參數(shù)后其他方法觸發(fā)了CMS,如果有知曉的朋友請(qǐng)留言告知,最后的方案還是徹底禁掉了顯式GC調(diào)用。最終定稿的參數(shù):
-server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m
-XX:PermSize=64m -XX:MaxPermSize=64m -XX:+UseConcMarkSweepGC
-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0
-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
-XX:SurvivorRatio=8
刪除了+CMSPermGenSweepingEnabled,這個(gè)參數(shù)在jdk6上跟-XX:+CMSClassUnloadingEnabled作用重疊了,如果你還跑在jdk5上面,那么應(yīng)該使用這個(gè)參數(shù)。救助空間設(shè)置為NewSize的1/10,也就是25M左右,讓年輕代盡量回收,防止年輕對(duì)象跑到年老代過(guò)早觸發(fā)CMS甚至full gc。CMS的觸發(fā)閥值下降到70%,因?yàn)槟昀洗鲩L(zhǎng)較慢,寧愿回收次數(shù)多一點(diǎn),降低長(zhǎng)暫停的可能。
24小時(shí)內(nèi)的某臺(tái)生產(chǎn)機(jī)器的表現(xiàn),通過(guò)jstat觀察:
CMS兩次暫停時(shí)間總和在100ms以下,minor gc平均一次執(zhí)行花了16ms,平均3-4秒發(fā)生一次。暫時(shí)來(lái)看還不錯(cuò),也許還可以適當(dāng)調(diào)小一下NewSize,加快以下minor gc。
此次調(diào)整總共花了大概一周多的時(shí)間,由于經(jīng)驗(yàn)不足,還是走了不少?gòu)澛?,幸好最終的結(jié)果還可以,也讓自己對(duì)cms gc有比較深入的了解。我們的系統(tǒng)在周4晚上已經(jīng)全部更新上線,從內(nèi)部測(cè)試、壓測(cè)、日常測(cè)試、beta測(cè)試以來(lái),每個(gè)階段都發(fā)現(xiàn)幾個(gè)隱蔽的問(wèn)題,在上線后暫時(shí)沒(méi)有再發(fā)現(xiàn)問(wèn)題,證明這個(gè)流程還是很有意義的,我過(guò)去對(duì)流程充滿偏見(jiàn),現(xiàn)在看來(lái)是可笑的??偨Y(jié)我在淘寶5個(gè)月越來(lái)學(xué)習(xí)到的東西,幾個(gè)關(guān)鍵詞:認(rèn)真、負(fù)責(zé)、細(xì)心、快樂(lè)。
那么最后是怎么解決的呢?其實(shí)沒(méi)有解決。我只是替換了一個(gè)參數(shù)就沒(méi)再發(fā)生這個(gè)現(xiàn)象,上文提到為了避免System.gc()調(diào)用引起的full gc,使用了jdk6引入的新參數(shù)-XX:+ExplicitGCInvokesConcurrent來(lái)讓System.gc()并發(fā)執(zhí)行,但是測(cè)試表明恰恰是這個(gè)參數(shù)引起了CMS的頻繁發(fā)生,去掉這個(gè)參數(shù)就沒(méi)有那個(gè)奇特的現(xiàn)象。重復(fù)檢查了代碼,并且再次查看了GC日志,沒(méi)有再發(fā)現(xiàn)有System.gc()的調(diào)用,我暫時(shí)將原因歸結(jié)于使用了ExplicitGCInvokesConcurrent參數(shù)后其他方法觸發(fā)了CMS,如果有知曉的朋友請(qǐng)留言告知,最后的方案還是徹底禁掉了顯式GC調(diào)用。最終定稿的參數(shù):
-server -Xms1536m -Xmx1536m -XX:NewSize=256m -XX:MaxNewSize=256m
-XX:PermSize=64m -XX:MaxPermSize=64m -XX:+UseConcMarkSweepGC
-XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0
-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC
-XX:SurvivorRatio=8
刪除了+CMSPermGenSweepingEnabled,這個(gè)參數(shù)在jdk6上跟-XX:+CMSClassUnloadingEnabled作用重疊了,如果你還跑在jdk5上面,那么應(yīng)該使用這個(gè)參數(shù)。救助空間設(shè)置為NewSize的1/10,也就是25M左右,讓年輕代盡量回收,防止年輕對(duì)象跑到年老代過(guò)早觸發(fā)CMS甚至full gc。CMS的觸發(fā)閥值下降到70%,因?yàn)槟昀洗鲩L(zhǎng)較慢,寧愿回收次數(shù)多一點(diǎn),降低長(zhǎng)暫停的可能。
24小時(shí)內(nèi)的某臺(tái)生產(chǎn)機(jī)器的表現(xiàn),通過(guò)jstat觀察:
S0 S1 E O P YGC YGCT FGC FGCT GCT
39.70 0.00 5.59 15.15 28.99 20260 326.041 14 0.592 326.633
39.70 0.00 65.49 15.15 28.99 20260 326.041 14 0.592 326.633
0.00 36.93 19.37 15.16 29.01 20261 326.059 14 0.592 326.650
0.00 36.93 93.23 15.16 29.01 20261 326.059 14 0.592 326.650
34.04 0.00 59.62 15.17 29.01 20262 326.076 14 0.592 326.668
0.00 38.55 12.76 15.19 29.01 20263 326.094 14 0.592 326.686
0.00 38.55 65.48 15.19 29.01 20263 326.094 14 0.592 326.686
39.70 0.00 5.59 15.15 28.99 20260 326.041 14 0.592 326.633
39.70 0.00 65.49 15.15 28.99 20260 326.041 14 0.592 326.633
0.00 36.93 19.37 15.16 29.01 20261 326.059 14 0.592 326.650
0.00 36.93 93.23 15.16 29.01 20261 326.059 14 0.592 326.650
34.04 0.00 59.62 15.17 29.01 20262 326.076 14 0.592 326.668
0.00 38.55 12.76 15.19 29.01 20263 326.094 14 0.592 326.686
0.00 38.55 65.48 15.19 29.01 20263 326.094 14 0.592 326.686
CMS兩次暫停時(shí)間總和在100ms以下,minor gc平均一次執(zhí)行花了16ms,平均3-4秒發(fā)生一次。暫時(shí)來(lái)看還不錯(cuò),也許還可以適當(dāng)調(diào)小一下NewSize,加快以下minor gc。
此次調(diào)整總共花了大概一周多的時(shí)間,由于經(jīng)驗(yàn)不足,還是走了不少?gòu)澛?,幸好最終的結(jié)果還可以,也讓自己對(duì)cms gc有比較深入的了解。我們的系統(tǒng)在周4晚上已經(jīng)全部更新上線,從內(nèi)部測(cè)試、壓測(cè)、日常測(cè)試、beta測(cè)試以來(lái),每個(gè)階段都發(fā)現(xiàn)幾個(gè)隱蔽的問(wèn)題,在上線后暫時(shí)沒(méi)有再發(fā)現(xiàn)問(wèn)題,證明這個(gè)流程還是很有意義的,我過(guò)去對(duì)流程充滿偏見(jiàn),現(xiàn)在看來(lái)是可笑的??偨Y(jié)我在淘寶5個(gè)月越來(lái)學(xué)習(xí)到的東西,幾個(gè)關(guān)鍵詞:認(rèn)真、負(fù)責(zé)、細(xì)心、快樂(lè)。