一次簡(jiǎn)單的G1GC參數(shù)調(diào)優(yōu)

緣起

交易的查詢服務(wù)調(diào)用組件的ES進(jìn)行查詢，ES服務(wù)會(huì)間歇性的3-4天抖動(dòng)一次（發(fā)生mixedGC），每次mixedgc耗時(shí)都在700ms+，而正常的dubbo超時(shí)設(shè)置在1s左右，所以當(dāng)發(fā)生GC的時(shí)候會(huì)引起短時(shí)集中式的查詢超時(shí)，引起大量報(bào)警，而在之前的處理手段都是手動(dòng)在凌晨四點(diǎn)觸發(fā)GC，防止白天對(duì)業(yè)務(wù)應(yīng)用產(chǎn)生抖動(dòng)。

插曲

這里要糾正一個(gè)很多人的誤解，為什么G1老年代的收集叫做mixedGC？
首先G1的進(jìn)行老年代垃圾回收的時(shí)候不一定是全部的老年代，一般是部分的old region，然后因?yàn)槔夏甑氖占强梢院蛓oung gc同時(shí)進(jìn)行的，所以叫mixedgc。

大部分我遇見(jiàn)以及協(xié)助排查的GC案例中幾乎最終都是代碼的問(wèn)題，比較令人的滿意的一個(gè)系統(tǒng)運(yùn)行的場(chǎng)景其實(shí)是每次Ygc都能很好的消化掉垃圾對(duì)象，畢竟G1垃圾收集器的默認(rèn)參數(shù)又少、又不錯(cuò)。

開(kāi)始

（如上圖）我們從一個(gè)正常來(lái)說(shuō)服務(wù)調(diào)用的鏈路說(shuō)起：
從鏈路追蹤來(lái)看，上游應(yīng)用發(fā)送請(qǐng)求的時(shí)間和下游開(kāi)始處理請(qǐng)求的時(shí)間應(yīng)該相差無(wú)幾。但是，一個(gè)rpc過(guò)程拋開(kāi)業(yè)務(wù)邏輯中間需要哪些過(guò)程呢？

（此圖從網(wǎng)上copy，如有抄襲嫌疑，請(qǐng)聯(lián)系我刪除狗頭保命）
可以看到，有序列化，網(wǎng)絡(luò)傳輸?shù)鹊?。那一般接口超時(shí)會(huì)有哪些因素引起呢？
窮舉法：網(wǎng)絡(luò)問(wèn)題、服務(wù)硬件問(wèn)題、GC問(wèn)題等

歷史重現(xiàn)

X月XX日，線上查詢服務(wù)又一次發(fā)生了抖動(dòng)，于是公司內(nèi)某張姓大佬過(guò)來(lái)問(wèn)我,對(duì)話如下：
張大佬：雞哥，請(qǐng)教個(gè)問(wèn)題
雞哥：你說(shuō)說(shuō)看，我應(yīng)該不會(huì)（）
張大佬：G1中加了-XX:+ParallelRefProcEnabled參數(shù)之后，GC耗時(shí)還是會(huì)很長(zhǎng)，導(dǎo)致一波超時(shí)，你知道什么情況么？
雞哥：你確定么？

我們來(lái)分析下這個(gè)參數(shù)，按道理來(lái)說(shuō)這個(gè)參數(shù)（-XX:+ParallelRefProcEnabled）的含義是：盡可能啟用并行引用處理
那好，
我們探索下他為什么要加這個(gè)參數(shù)？是出現(xiàn)了什么現(xiàn)象讓他要加這個(gè)參數(shù)？
原來(lái)是張姓大佬通過(guò)gclog發(fā)現(xiàn)每次GC的【ref proc】階段耗時(shí)比較長(zhǎng)，于是他從網(wǎng)上搜索到了這個(gè)參數(shù)之后就加上試了一下

現(xiàn)象

如上圖我們可以發(fā)現(xiàn)在gc過(guò)程中 ref-proc（mixedgc）階段發(fā)生了700ms+的暫停
那

【ref proc】階段到底是干什么的？

其實(shí)是對(duì)各種軟弱虛引用等的處理
圖中ref-proc 0.7034259 secs 就是處理 soft、weak、phantom、final、JNI 等等引用的時(shí)間
Oracle官方文檔如下描述：
其實(shí)是在G1的remark階段，對(duì)上述的引用根據(jù)其特定類型更新所指對(duì)象

額外分析

這又得從G1的Ygc說(shuō)起，我們都知道，Ygc就是對(duì)象填滿Eden區(qū)然后觸發(fā)Ygc，而正常來(lái)說(shuō)G1中有設(shè)置

• -XX:MaxGCPauseMillis GC 最大停頓時(shí)間，默認(rèn) 200ms 這個(gè)參數(shù)會(huì)影響到Y(jié)gc的STW時(shí)間，為什么呢？我們思考一下， MaxGCPauseMillis 時(shí)間越小，給STW時(shí)間也就越小，年輕代大概率就越小；反之 MaxGCPauseMillis 時(shí)間越大，給STW時(shí)間也就越大，年輕代大概率就會(huì)越大。此時(shí)是不是有人會(huì)有疑問(wèn)？那我為了減少STW的時(shí)間，我就去降低MaxGCPauseMillis
  此言差矣?。。?！
  MaxGCPauseMillis 越小，年輕代也越小，從而導(dǎo)致有很多短生命周期的對(duì)象被過(guò)早晉升到老年代。而老年代你們都懂的，標(biāo)記清理過(guò)程比年輕代要復(fù)雜的多，整體效率也低，就導(dǎo)致雖然GC停滯時(shí)間下降了，但GC次數(shù)可能增多，整體吞吐量下降的情況。并且GC次數(shù)增多也會(huì)導(dǎo)致對(duì)CPU資源的占用增加，跟業(yè)務(wù)線程一起爭(zhēng)搶CPU

第一次處理

然后當(dāng)天晚點(diǎn)時(shí)間，我被拉進(jìn)一個(gè)三人組成的GC問(wèn)題處理群

實(shí)驗(yàn)了
三組對(duì)比參數(shù)

未調(diào)試:沒(méi)有加ParallelRefProcEnabled，年輕代自動(dòng)分配了17g，Ygc（40ms），mixedgc （500ms）
調(diào)試1:-XX:+ParallelRefProcEnabled，年輕代自動(dòng)分配了2g，Ygc（50ms），Ygc次數(shù)增加，mixedgc（200ms）
調(diào)試2:-XX:+ParallelRefProcEnabled和-XX:ParallelgCThreads=8，年輕代17g，Ygc（40ms），Ygc次數(shù)與未調(diào)試的情況差不多，mixedgc還沒(méi)有觸發(fā)，所以耗時(shí)未知

我們可以基本上看到很明顯的問(wèn)題就是通過(guò)加入(-XX:+ParallelRefProcEnabled)
現(xiàn)象：

總結(jié)一

其實(shí)我們發(fā)現(xiàn)官網(wǎng)推薦的指導(dǎo)手段，讓gc時(shí)間從700ms+下降到300ms左右，但是對(duì)于業(yè)務(wù)側(cè)還是會(huì)引起一波超時(shí)抖動(dòng)

第二次處理

當(dāng)然300ms完全沒(méi)辦法支撐，還是會(huì)帶來(lái)大量抖動(dòng)，但是現(xiàn)有的gclog不夠觀察到本質(zhì)，于是我推薦了如下參數(shù)，觀測(cè)更具體的信息
-XX:+PrintReferenceGC

第二次現(xiàn)象

終于在X月X號(hào)，終于觸發(fā)了一次Mixedgc，日志也出來(lái)了（如下）

第二次處理

我們可以看到Softreference和FinalReference 占了兩個(gè)大頭，一個(gè)是132ms，一個(gè)255ms
其實(shí)問(wèn)題幾乎就已經(jīng)快壓縮到最后了，此時(shí)可以看到Application stop 621ms

第三次現(xiàn)象

于是，問(wèn)題定位到了就可以著手去解決了！
因?yàn)檐浺么蠹叶贾?，?nèi)存不足的時(shí)候才會(huì)去收集，所以項(xiàng)目中生成的軟引用對(duì)象太多的話，會(huì)在gc過(guò)程中產(chǎn)生較大的處理壓力
我們這次加上了 -XX:SoftRefLRUPolicyMSPerMB=0

官方解釋：Soft reference在虛擬機(jī)中比在客戶集中存活的更長(zhǎng)一些。其清除頻率可以用命令行參數(shù) -XX:SoftRefLRUPolicyMSPerMB=<N>來(lái)控制，這可以指定每兆堆空閑空間的 soft reference 保持存活（一旦它不強(qiáng)可達(dá)了）的毫秒數(shù)，這意味著每兆堆中的空閑空間中的 soft reference 會(huì)（在最后一個(gè)強(qiáng)引用被回收之后）存活1秒鐘。注意，這是一個(gè)近似的值，因?yàn)?soft reference 只會(huì)在垃圾回收時(shí)才會(huì)被清除，而垃圾回收并不總在發(fā)生。系統(tǒng)默認(rèn)為一秒，我覺(jué)得沒(méi)必要等1秒，客戶集中不用就立刻清除，改為 -XX:SoftRefLRUPolicyMSPerMB=0；

第三次結(jié)果

結(jié)果是什么？

我們可以看到的現(xiàn)象是 soft引用和final引用在每次Ygc過(guò)程中都被收集掉一部分，且數(shù)量比之前大一倍
而finalReference的疑問(wèn)是什么呢？
因?yàn)樵趈ava8的SocketServiceImpl里實(shí)現(xiàn)了Object的finalize方法，為了防止socket鏈接忘了釋放資源，而進(jìn)行幫助釋放

當(dāng)有大量短鏈接未來(lái)得及釋放，會(huì)導(dǎo)致Finalizer對(duì)象過(guò)多，引起一開(kāi)始我們看到的現(xiàn)象，所以猜測(cè)ES使用的OKHTTP的調(diào)用方式，但是無(wú)法dump，所以無(wú)從考證
但因?yàn)橐呀?jīng)在每次Ygc中進(jìn)行收集了，其實(shí)也算是達(dá)到預(yù)期，但是不是很完美。
當(dāng)然好像JDK9中的AbstractPlainSocketImpl已經(jīng)不再?gòu)?fù)寫finalize方法了，因?yàn)閒inallize() 方法是Object類的方法, 用于在類被GC回收時(shí) 做一些處理操作, 但是JVM并不能保證finalize() 方法一定被執(zhí)行,由finalize()方法的調(diào)用時(shí)機(jī)具有不確定性，從一個(gè)對(duì)象變得不可到達(dá)開(kāi)始，到finalize()方法被執(zhí)行，所花費(fèi)的時(shí)間這段時(shí)間是任意長(zhǎng)的。我們并不能依賴finalize()方法能及時(shí)的回收占用的資源，可能出現(xiàn)的情況是在我們耗盡資源之前，gc卻仍未觸發(fā)，因而通常的做法是提供顯示的close()方法供客戶端手動(dòng)調(diào)用

小插曲

不少人的認(rèn)知是soft引用會(huì)在內(nèi)存不足時(shí)候回收？其實(shí)不一定，軟引用的回收是需要一定條件的我們看官方文檔怎么說(shuō)

clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB
clock：上次GC的時(shí)間戳
timestamp：表示最近一次讀取軟引用對(duì)象的時(shí)間戳
這兩者的差值表示該軟引用對(duì)象多久沒(méi)被使用了，差值越大，軟引用對(duì)象價(jià)值越低，負(fù)數(shù)則表示軟引用對(duì)象剛剛被使用
freespace是空閑空間大小，SoftRefLRUPolicyMSPerMB表示每一MB的空閑內(nèi)存空間可以允許軟引用對(duì)象存活多久，這也就間接的解釋了，為什么空間不夠用，空閑空間越小，軟應(yīng)用對(duì)象就會(huì)被回收，因?yàn)樗拇婊顣r(shí)間會(huì)隨著空閑空間的減小而遞減?？梢园?【freespace * SoftRefLRUPolicyMSPerMB】理解為忍耐度，對(duì)軟應(yīng)用對(duì)象的忍耐程度。

等待

其實(shí)從gclog和現(xiàn)象之中大概已經(jīng)猜測(cè)到基本上已經(jīng)算是成功了，但是呢，加上這個(gè)參數(shù)【SoftRefLRUPolicyMSPerMB】也是有風(fēng)險(xiǎn)的，如下我說(shuō)的
例子：假設(shè)程序中有很多反射創(chuàng)建類的操作，因?yàn)榉瓷鋭?chuàng)建的類本身的Class對(duì)象都是被SoftReference軟引用的，加上了如上的參數(shù)，軟引用就會(huì)被盡快的釋放掉，所以就會(huì)產(chǎn)生，反射創(chuàng)建大量類->剛創(chuàng)建完GC回收掉很多->反射執(zhí)行繼續(xù)創(chuàng)建大量類，最終導(dǎo)致Metaspace區(qū)域被打滿->導(dǎo)致FullGC

結(jié)果

等待了4天之后，聽(tīng)著張姓大佬一陣激動(dòng)的叫喊

發(fā)現(xiàn)mixedgc已經(jīng)穩(wěn)定到85ms左右

小插曲

1.為什么軟引用收集參數(shù)【SoftRefLRUPolicyMSPerMB】沒(méi)有在jvm中默認(rèn)打開(kāi)？
答：因?yàn)檐浺玫奶匦蕴貏e適合做Cache，設(shè)計(jì)者目的就是想讓cache常駐內(nèi)存，所以要到內(nèi)存不夠的時(shí)候才去觸發(fā)收集

2.是否要引用ZGC？
中間有人給張姓大佬推薦了ZGC,于是我掏出了這種圖，JDK11開(kāi)始有的，也是2018年9月左右發(fā)布，
第一，可以嘗試，但是這算是屏蔽了問(wèn)題，而走捷徑；
第二，沒(méi)有人完全能hold住，出了問(wèn)題誰(shuí)來(lái)負(fù)責(zé)和修復(fù)？

GC調(diào)優(yōu)的幾個(gè)核心要素

一.要有信心

二.不斷壓縮問(wèn)題到死角

三.多組參數(shù)實(shí)驗(yàn)對(duì)比

畢竟沒(méi)有兼容所有場(chǎng)景的參數(shù)，只有符合自己業(yè)務(wù)場(chǎng)景的參數(shù)調(diào)優(yōu)

附件（給大家參考借鑒，gclog中每個(gè)步驟在干什么）：

[GC pause (G1 Evacuation Pause) (young), 0.0022483 secs]
young -> 年輕代 Evacuation-> 復(fù)制存活對(duì)象 
[Parallel Time: 1.0 ms, GC Workers: 10] # 并發(fā)執(zhí)行的GC線程數(shù)，以下階段是并發(fā)執(zhí)行的
[GC Worker Start (ms): Min: 109.0, Avg: 109.1, Max: 109.1, Diff: 0.2] 
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 2.3] # 外部根分區(qū)掃描
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # 更新已記憶集合 Update RSet，檢測(cè)從年輕代指向老年代的對(duì)象
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] 
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]# RSet掃描
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] # 代碼根掃描
[Object Copy (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.1, Sum: 3.5] # 轉(zhuǎn)移和回收，拷貝存活的對(duì)象到survivor/old區(qū)域
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # 完成上述任務(wù)后，如果任務(wù)隊(duì)列已空，則工作線程會(huì)發(fā)起終止要求。
[Termination Attempts: Min: 1, Avg: 5.8, Max: 9, Diff: 8, Sum: 58]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] # GC外部的并行活動(dòng)，該部分并非GC的活動(dòng)，而是JVM的活動(dòng)導(dǎo)致占用了GC暫停時(shí)間(例如JNI編譯)。
[GC Worker Total (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 5.9]
[GC Worker End (ms): Min: 109.7, Avg: 109.7, Max: 109.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms] # 串行任務(wù)，根據(jù)轉(zhuǎn)移對(duì)象更新代碼根
[Code Root Purge: 0.0 ms] #串行任務(wù)， 代碼根清理
[Clear CT: 0.5 ms] #串行任務(wù)，清除全局卡片 Card Table 標(biāo)記
[Other: 0.8 ms]
[Choose CSet: 0.0 ms] # 選擇下次收集集合 CSet
[Ref Proc: 0.4 ms] # 引用處理 Ref Proc，處理軟引用、弱引用、虛引用、final引用、JNI引用
[Ref Enq: 0.0 ms] # 引用排隊(duì) Ref Enq
[Redirty Cards: 0.3 ms] # 卡片重新臟化 Redirty Cards：重新臟化卡片
[Humongous Register: 0.0 ms] 
[Humongous Reclaim: 0.0 ms] # 回收空閑巨型分區(qū) Humongous Reclaim，通過(guò)查看所有根對(duì)象以及年輕代分區(qū)的RSet，如果確定RSet中巨型對(duì)象沒(méi)有任何引用，該對(duì)象分區(qū)會(huì)被回收。
[Free CSet: 0.0 ms] # 釋放分區(qū) Free CSet
[Eden: 12288.0K(12288.0K)->0.0B(11264.0K) Survivors: 0.0B->1024.0K Heap: 12288.0K(20480.0K)->832.0K(20480.0K)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
從年輕代分區(qū)拷貝存活對(duì)象時(shí)，無(wú)法找到可用的空閑分區(qū)
從老年代分區(qū)轉(zhuǎn)移存活對(duì)象時(shí)，無(wú)法找到可用的空閑分區(qū) 這兩種情況之一導(dǎo)致的 YGC
[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0916534 secs]
并發(fā)標(biāo)記周期 Concurrent Marking Cycle 中的 根分區(qū)掃描階段，被 YGC中斷
[GC pause (G1 Evacuation Pause) (young)[GC concurrent-root-region-scan-end, 0.0007157 secs]