通過這一個多月的努力,將FullGC從40次/天優化到近10天才觸發一次,而且YoungGC的時間也減少了一半以上,這么大的優化,有必要記錄一下中間的調優過程。
對於JVM垃圾回收,之前一直都是處於理論階段,就知道新生代,老年代的晉升關系,這些知識僅夠應付面試使用的。前一段時間,線上服務器的FullGC非常頻繁,平均一天40多次,而且隔幾天就有服務器自動重啟了,這表明的服務器的狀態已經非常不正常了,得到這么好的機會,當然要主動請求進行調優了。未調優前的服務器GC數據,FullGC非常頻繁。
首先服務器的配置非常一般(2核4G),總共4台服務器集群。每台服務器的FullGC次數和時間基本差不多。其中JVM幾個核心的啟動參數為:
-Xms1000M -Xmx1800M -Xmn350M -Xss300K -XX:+DisableExplicitGC -XX:SurvivorRatio=4 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:LargePageSizeInBytes=128M -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC
1
2
-Xmx1800M:設置JVM最大可用內存為1800M。
-Xms1000m:設置JVM初始化內存為1000m。此值可以設置與-Xmx相同,以避免每次垃圾回收完成后JVM重新分配內存。
-Xmn350M:設置年輕代大小為350M。整個JVM內存大小=年輕代大小 + 年老代大小 + 持久代大小。持久代一般固定大小為64m,所以增大年輕代后,將會減小年老代大小。此值對系統性能影響較大,Sun官方推薦配置為整個堆的3/8。
-Xss300K:設置每個線程的堆棧大小。JDK5.0以后每個線程堆棧大小為1M,以前每個線程堆棧大小為256K。更具應用的線程所需內存大小進行調整。在相同物理內存下,減小這個值能生成更多的線程。但是操作系統對一個進程內的線程數還是有限制的,不能無限生成,經驗值在3000~5000左右。
第一次優化
一看參數,馬上覺得新生代為什么這么小,這么小的話怎么提高吞吐量,而且會導致YoungGC的頻繁觸發,如上如的新生代收集就耗時830s。初始化堆內存沒有和最大堆內存一致,查閱了各種資料都是推薦這兩個值設置一樣的,可以防止在每次GC后進行內存重新分配。基於前面的知識,於是進行了第一次的線上調優:提升新生代大小,將初始化堆內存設置為最大內存
-Xmn350M -> -Xmn800M
-XX:SurvivorRatio=4 -> -XX:SurvivorRatio=8
-Xms1000m ->-Xms1800m
將SurvivorRatio修改為8的本意是想讓垃圾在新生代時盡可能的多被回收掉。就這樣將配置部署到線上兩台服務器(prod,prod2另外兩台不變方便對比)上后,運行了5天后,觀察GC結果,YoungGC減少了一半以上的次數,時間減少了400s,但是FullGC的平均次數增加了41次。YoungGC基本符合預期設想,但是這個FullGC就完全不行了。
就這樣第一次優化宣告失敗。
第二次優化
在優化的過程中,我們的主管發現了有個對象T在內存中有一萬多個實例,而且這些實例占據了將近20M的內存。於是根據這個bean對象的使用,在項目中找到了原因:匿名內部類引用導致的,偽代碼如下:
public void doSmthing(T t){
redis.addListener(new Listener(){
public void onTimeout(){
if(t.success()){
//執行操作
}
}
});
}
1
2
3
4
5
6
7
8
9
由於listener在回調后不會進行釋放,而且回調是個超時的操作,當某個事件超過了設定的時間(1分鍾)后才會進行回調,這樣就導致了T這個對象始終無法回收,所以內存中會存在這么多對象實例。
通過上述的例子發現了存在內存泄漏后,首先對程序中的error log文件進行排查,首先先解決掉所有的error事件。然后再次發布后,GC操作還是基本不變,雖然解決了一點內存泄漏問題,但是可以說明沒有解決根本原因,服務器還是繼續莫名的重啟。
內存泄漏調查
經過了第一次的調優后發現內存泄漏的問題,於是大家都開始將進行內存泄漏的調查,首先排查代碼,不過這種效率是蠻低的,基本沒發現問題。於是在線上不是很繁忙的時候繼續進行dump內存,終於抓到了一個大對象
這個對象竟然有4W多個,而且都是清一色的ByteArrowRow對象,可以確認這些數據是數據庫查詢或者插入時產生的了。於是又進行一輪代碼分析,在代碼分析的過程中,通過運維的同事發現了在一天的某個時候入口流量翻了好幾倍,竟然高達83MB/s,經過一番確認,目前完全沒有這么大的業務量,而且也不存在文件上傳的功能。咨詢了阿里雲客服也說明完全是正常的流量,可以排除攻擊的可能。
就在我還在調查入口流量的問題時,另外一個同事找到了根本的原因,原來是在某個條件下,會查詢表中所有未處理的指定數據,但是由於查詢的時候where條件中少加了模塊這個條件,導致查詢出的數量達40多萬條,而且通過log查看當時的請求和數據,可以判斷這個邏輯確實是已經執行了的,dump出的內存中只有4W多個對象,這個是因為dump時候剛好查詢出了這么多個,剩下的還在傳輸中導致的。而且這也能非常好的解釋了為什么服務器會自動重啟的原因。
解決了這個問題后,線上服務器運行完全正常了,使用未調優前的參數,運行了3天左右FullGC只有5次
第二次調優
內存泄漏的問題已經解決了,剩下的就可以繼續調優了,經過查看GC log,發現前三次GullGC時,老年代占據的內存還不足30%,卻發生了FullGC。於是進行各種資料的調查,在https://blog.csdn.net/zjwstz/article/details/77478054 博客中非常清晰明了的說明metaspace導致FullGC的情況,服務器默認的metaspace是21M,在GC log中看到了最大的時候metaspace占據了200M左右,於是進行如下調優,以下分別為prod1和prod2的修改參數,prod3,prod4保持不變
-Xmn350M -> -Xmn800M
-Xms1000M ->1800M
-XX:MetaspaceSize=200M
-XX:CMSInitiatingOccupancyFraction=75
和
-Xmn350M -> -Xmn600M
-Xms1000M ->1800M
-XX:MetaspaceSize=200M
-XX:CMSInitiatingOccupancyFraction=75
prod1和2只是新生代大小不一樣而已,其他的都一致。到線上運行了10天左右,進行對比:
prod1:
prod2:
prod3:
prod4:
對比來說,1,2兩台服務器FullGC遠遠低於3,4兩台,而且1,2兩台服務器的YounGC對比3,4也減少了一半左右,而且第一台服務器效率更為明顯,除了YoungGC次數減少,而且吞吐量比多運行了一天的3,4兩台的都要多(通過線程啟動數量),說明prod1的吞吐量提升尤為明顯。
通過GC的次數和GC的時間,本次優化宣告成功,且prod1的配置更優,極大提升了服務器的吞吐量和降低了GC一半以上的時間。
prod1中的唯一一次FullGC:
通過GC log上也沒看出原因,老年代在cms remark的時候只占據了660M左右,這個應該還不到觸發FullGC的條件,而且通過前幾次的YoungGC調查,也排除了晉升了大內存對象的可能,通過metaspace的大小,也沒有達到GC的條件。這個還需要繼續調查,有知道的歡迎指出下,這里先行謝過了。
總結
通過這一個多月的調優總結出以下幾點:
FullGC一天超過一次肯定就不正常了
發現FullGC頻繁的時候優先調查內存泄漏問題
內存泄漏解決后,jvm可以調優的空間就比較少了,作為學習還可以,否則不要投入太多的時間
如果發現CPU持續偏高,排除代碼問題后可以找運維咨詢下阿里雲客服,這次調查過程中就發現CPU 100%是由於服務器問題導致的,進行服務器遷移后就正常了。
數據查詢的時候也是算作服務器的入口流量的,如果訪問業務沒有這么大量,而且沒有攻擊的問題的話可以往數據庫方面調查
有必要時常關注服務器的GC,可以及早發現問題
以上是最近一個多月JVM調優的過程與總結,如有錯誤之處歡迎指正。
參考博客:
https://blog.csdn.net/zjwstz/article/details/77478054
https://www.cnblogs.com/onmyway20xx/p/6590603.html
————————————————
原文鏈接:https://blog.csdn.net/cml_blog/article/details/81057966