Posted on 2009-09-26 18:29
dennis 閱讀(2100)
評論(1) 編輯 收藏 所屬分類:
java
本以為在上篇定稿的參數后應該能有比較好的表現，然后實際的表現大出我的意料，cms回收觸發非常頻繁，雖然每次都只是10-50毫秒，但是次數12個小時內能達到180多次，這顯然不正常。通過gc日志和jstat可以看到，每次old區還在5%左右就開始進行CMS，此時的perm區也才30%，這兩個數字有浮動并且CMS觸發的時間上也沒有規律，在測試環境和生產環境中都是如此。
那么最后是怎么解決的呢？其實沒有解決。我只是替換了一個參數就沒再發生這個現象，上文提到為了避免System.gc()調用引起的full gc，使用了jdk6引入的新參數-XX:+ExplicitGCInvokesConcurrent來讓System.gc()并發執行，但是測試表明恰恰是這個參數引起了CMS的頻繁發生，去掉這個參數就沒有那個奇特的現象。重復檢查了代碼，并且再次查看了GC日志，沒有再發現有System.gc()的調用，我暫時將原因歸結于使用了ExplicitGCInvokesConcurrent參數后其他方法觸發了CMS，如果有知曉的朋友請留言告知，最后的方案還是徹底禁掉了顯式GC調用。最終定稿的參數：
-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，這個參數在jdk6上跟-XX:+CMSClassUnloadingEnabled作用重疊了，如果你還跑在jdk5上面，那么應該使用這個參數。救助空間設置為NewSize的1/10，也就是25M左右，讓年輕代盡量回收，防止年輕對象跑到年老代過早觸發CMS甚至full gc。CMS的觸發閥值下降到70%，因為年老代增長較慢，寧愿回收次數多一點，降低長暫停的可能。
24小時內的某臺生產機器的表現，通過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
CMS兩次暫停時間總和在100ms以下，minor gc平均一次執行花了16ms，平均3-4秒發生一次。暫時來看還不錯，也許還可以適當調小一下NewSize，加快以下minor gc。
此次調整總共花了大概一周多的時間，由于經驗不足，還是走了不少彎路，幸好最終的結果還可以，也讓自己對cms gc有比較深入的了解。我們的系統在周4晚上已經全部更新上線，從內部測試、壓測、日常測試、beta測試以來，每個階段都發現幾個隱蔽的問題，在上線后暫時沒有再發現問題，證明這個流程還是很有意義的，我過去對流程充滿偏見，現在看來是可笑的。總結我在淘寶5個月越來學習到的東西，幾個關鍵詞：認真、負責、細心、快樂。