從FullGC頻繁到穩(wěn)定運(yùn)行：JVM優(yōu)化之旅

作者：一安 2024-01-29 08:24:40

通過GC log上也沒看出原因，老年代在cms remark的時(shí)候只占據(jù)了660M左右，這個(gè)應(yīng)該還不到觸發(fā)FullGC的條件，而且通過前幾次的YoungGC調(diào)查，也排除了晉升了大內(nèi)存對(duì)象的可能，通過metaspace的大小，也沒有達(dá)到GC的條件。這個(gè)還需要繼續(xù)調(diào)查，有知道的歡迎指出下，這里先行謝過了。

通過這一個(gè)多月的努力，將FullGC從40次/天優(yōu)化到近10天才觸發(fā)一次，而且YoungGC的時(shí)間也減少了一半以上，這么大的優(yōu)化，有必要記錄一下中間的調(diào)優(yōu)過程。

對(duì)于JVM垃圾回收，之前一直都是處于理論階段，就知道新生代，老年代的晉升關(guān)系，這些知識(shí)僅夠應(yīng)付面試使用的。前一段時(shí)間，線上服務(wù)器的FullGC非常頻繁，平均一天40多次，而且隔幾天就有服務(wù)器自動(dòng)重啟了，這表明服務(wù)器的狀態(tài)已經(jīng)非常不正常了，得到這么好的機(jī)會(huì)，當(dāng)然要主動(dòng)請(qǐng)求進(jìn)行調(diào)優(yōu)了。未調(diào)優(yōu)前的服務(wù)器GC數(shù)據(jù)，F(xiàn)ullGC非常頻繁。

圖片

首先服務(wù)器的配置非常一般（2核4G），總共4臺(tái)服務(wù)器集群。每臺(tái)服務(wù)器的FullGC次數(shù)和時(shí)間基本差不多。其中JVM幾個(gè)核心的啟動(dòng)參數(shù)為：

-Xms1000M -Xmx1800M -Xmn350M -Xss300K -XX:+DisableExplicitGC -XX:SurvivorRatio=4 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFractinotallow=70 -XX:+CMSParallelRemarkEnabled -XX:LargePageSizeInBytes=128M -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC

-Xmx1800M：設(shè)置JVM最大可用內(nèi)存為1800M。
-Xms1000m：設(shè)置JVM初始化內(nèi)存為1000m。此值可以設(shè)置與-Xmx相同，以避免每次垃圾回收完成后JVM重新分配內(nèi)存。
-Xmn350M：設(shè)置年輕代大小為350M。整個(gè)JVM內(nèi)存大小=年輕代大小 + 年老代大小 + 持久代大小。持久代一般固定大小為64m，所以增大年輕代后，將會(huì)減小年老代大小。此值對(duì)系統(tǒng)性能影響較大，Sun官方推薦配置為整個(gè)堆的3/8。
-Xss300K：設(shè)置每個(gè)線程的堆棧大小。JDK5.0以后每個(gè)線程堆棧大小為1M，以前每個(gè)線程堆棧大小為256K。更具應(yīng)用的線程所需內(nèi)存大小進(jìn)行調(diào)整。在相同物理內(nèi)存下，減小這個(gè)值能生成更多的線程。但是操作系統(tǒng)對(duì)一個(gè)進(jìn)程內(nèi)的線程數(shù)還是有限制的，不能無限生成，經(jīng)驗(yàn)值在3000~5000左右。

第一次優(yōu)化

一看參數(shù)，馬上覺得新生代為什么這么小，這么小的話怎么提高吞吐量，而且會(huì)導(dǎo)致YoungGC的頻繁觸發(fā)，如上如的新生代收集就耗時(shí)830s。初始化堆內(nèi)存沒有和最大堆內(nèi)存一致，查閱了各種資料都是推薦這兩個(gè)值設(shè)置一樣的，可以防止在每次GC后進(jìn)行內(nèi)存重新分配。基于前面的知識(shí)，于是進(jìn)行了第一次的線上調(diào)優(yōu)：提升新生代大小，將初始化堆內(nèi)存設(shè)置為最大內(nèi)存

-Xmn350M -> -Xmn800M
-XX:SurvivorRatio=4 -> -XX:SurvivorRatio=8
-Xms1000m ->-Xms1800m

將SurvivorRatio修改為8的本意是想讓垃圾在新生代時(shí)盡可能的多被回收掉。就這樣將配置部署到線上兩臺(tái)服務(wù)器（prod，prod2另外兩臺(tái)不變方便對(duì)比）上后，運(yùn)行了5天后，觀察GC結(jié)果，YoungGC減少了一半以上的次數(shù)，時(shí)間減少了400s，但是FullGC的平均次數(shù)增加了41次。YoungGC基本符合預(yù)期設(shè)想，但是這個(gè)FullGC就完全不行了。

圖片

就這樣第一次優(yōu)化宣告失敗。

第二次優(yōu)化

在優(yōu)化的過程中，我們的主管發(fā)現(xiàn)了有個(gè)對(duì)象T在內(nèi)存中有一萬多個(gè)實(shí)例，而且這些實(shí)例占據(jù)了將近20M的內(nèi)存。于是根據(jù)這個(gè)bean對(duì)象的使用，在項(xiàng)目中找到了原因：匿名內(nèi)部類引用導(dǎo)致的，偽代碼如下：

public void doSmthing(T t){
 redis.addListener(new Listener(){
  public void onTimeout(){
   if(t.success()){
    //執(zhí)行操作
   }
  }
 });
}

由于listener在回調(diào)后不會(huì)進(jìn)行釋放，而且回調(diào)是個(gè)超時(shí)的操作，當(dāng)某個(gè)事件超過了設(shè)定的時(shí)間（1分鐘）后才會(huì)進(jìn)行回調(diào)，這樣就導(dǎo)致了T這個(gè)對(duì)象始終無法回收，所以內(nèi)存中會(huì)存在這么多對(duì)象實(shí)例。

通過上述的例子發(fā)現(xiàn)了存在內(nèi)存泄漏后，首先對(duì)程序中的error log文件進(jìn)行排查，首先先解決掉所有的error事件。然后再次發(fā)布后，GC操作還是基本不變，雖然解決了一點(diǎn)內(nèi)存泄漏問題，但是可以說明沒有解決根本原因，服務(wù)器還是繼續(xù)莫名的重啟。

內(nèi)存泄漏調(diào)查

經(jīng)過了第一次的調(diào)優(yōu)后發(fā)現(xiàn)內(nèi)存泄漏的問題，于是大家都開始將進(jìn)行內(nèi)存泄漏的調(diào)查，首先排查代碼，不過這種效率是蠻低的，基本沒發(fā)現(xiàn)問題。于是在線上不是很繁忙的時(shí)候繼續(xù)進(jìn)行dump內(nèi)存，終于抓到了一個(gè)大對(duì)象

圖片

這個(gè)對(duì)象竟然有4W多個(gè)，而且都是清一色的ByteArrowRow對(duì)象，可以確認(rèn)這些數(shù)據(jù)是數(shù)據(jù)庫查詢或者插入時(shí)產(chǎn)生的了。于是又進(jìn)行一輪代碼分析，在代碼分析的過程中，通過運(yùn)維的同事發(fā)現(xiàn)了在一天的某個(gè)時(shí)候入口流量翻了好幾倍，竟然高達(dá)83MB/s，經(jīng)過一番確認(rèn)，目前完全沒有這么大的業(yè)務(wù)量，而且也不存在文件上傳的功能。咨詢了阿里云客服也說明完全是正常的流量，可以排除攻擊的可能。

圖片

就在我還在調(diào)查入口流量的問題時(shí)，另外一個(gè)同事找到了根本的原因，原來是在某個(gè)條件下，會(huì)查詢表中所有未處理的指定數(shù)據(jù)，但是由于查詢的時(shí)候where條件中少加了模塊這個(gè)條件，導(dǎo)致查詢出的數(shù)量達(dá)40多萬條，而且通過log查看當(dāng)時(shí)的請(qǐng)求和數(shù)據(jù)，可以判斷這個(gè)邏輯確實(shí)是已經(jīng)執(zhí)行了的，dump出的內(nèi)存中只有4W多個(gè)對(duì)象，這個(gè)是因?yàn)閐ump時(shí)候剛好查詢出了這么多個(gè)，剩下的還在傳輸中導(dǎo)致的。而且這也能非常好的解釋了為什么服務(wù)器會(huì)自動(dòng)重啟的原因。

解決了這個(gè)問題后，線上服務(wù)器運(yùn)行完全正常了，使用未調(diào)優(yōu)前的參數(shù)，運(yùn)行了3天左右FullGC只有5次

圖片

第二次調(diào)優(yōu)

內(nèi)存泄漏的問題已經(jīng)解決了，剩下的就可以繼續(xù)調(diào)優(yōu)了，經(jīng)過查看GC log，發(fā)現(xiàn)前三次GullGC時(shí)，老年代占據(jù)的內(nèi)存還不足30%，卻發(fā)生了FullGC。于是進(jìn)行各種資料的調(diào)查，服務(wù)器默認(rèn)的metaspace是21M，在GC log中看到了最大的時(shí)候metaspace占據(jù)了200M左右，于是進(jìn)行如下調(diào)優(yōu)，以下分別為prod1和prod2的修改參數(shù)，prod3，prod4保持不變

-Xmn350M -> -Xmn800M
-Xms1000M ->1800M
-XX:MetaspaceSize=200M
-XX:CMSInitiatingOccupancyFractinotallow=75

和

-Xmn350M -> -Xmn600M
-Xms1000M ->1800M
-XX:MetaspaceSize=200M
-XX:CMSInitiatingOccupancyFractinotallow=75

prod1和2只是新生代大小不一樣而已，其他的都一致。到線上運(yùn)行了10天左右，進(jìn)行對(duì)比：

prod1：

圖片

prod2：

圖片

prod3：

prod4：

圖片

對(duì)比來說，1，2兩臺(tái)服務(wù)器FullGC遠(yuǎn)遠(yuǎn)低于3，4兩臺(tái)，而且1，2兩臺(tái)服務(wù)器的YounGC對(duì)比3，4也減少了一半左右，而且第一臺(tái)服務(wù)器效率更為明顯，除了YoungGC次數(shù)減少，而且吞吐量比多運(yùn)行了一天的3，4兩臺(tái)的都要多（通過線程啟動(dòng)數(shù)量），說明prod1的吞吐量提升尤為明顯。通過GC的次數(shù)和GC的時(shí)間，本次優(yōu)化宣告成功，且prod1的配置更優(yōu)，極大提升了服務(wù)器的吞吐量和降低了GC一半以上的時(shí)間。

prod1中的唯一一次FullGC：

圖片

總結(jié)

通過這一個(gè)多月的調(diào)優(yōu)總結(jié)出以下幾點(diǎn)：

FullGC一天超過一次肯定就不正常了
發(fā)現(xiàn)FullGC頻繁的時(shí)候優(yōu)先調(diào)查內(nèi)存泄漏問題
內(nèi)存泄漏解決后，jvm可以調(diào)優(yōu)的空間就比較少了，作為學(xué)習(xí)還可以，否則不要投入太多的時(shí)間
如果發(fā)現(xiàn)CPU持續(xù)偏高，排除代碼問題后可以找運(yùn)維咨詢下阿里云客服，這次調(diào)查過程中就發(fā)現(xiàn)CPU 100%是由于服務(wù)器問題導(dǎo)致的，進(jìn)行服務(wù)器遷移后就正常了。
數(shù)據(jù)查詢的時(shí)候也是算作服務(wù)器的入口流量的，如果訪問業(yè)務(wù)沒有這么大量，而且沒有攻擊的問題的話可以往數(shù)據(jù)庫方面調(diào)查
有必要時(shí)常關(guān)注服務(wù)器的GC，可以及早發(fā)現(xiàn)問題

責(zé)任編輯：武曉燕來源：一安未來