一次簡(jiǎn)單的G1gc參數(shù)調(diào)優(yōu)
本文轉(zhuǎn)載自微信公眾號(hào)「再見伐木機(jī)」，作者再見伐木機(jī)。轉(zhuǎn)載本文請(qǐng)聯(lián)系再見伐木機(jī)公眾號(hào)。
緣起
交易的查詢服務(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。
大部分我遇見以及協(xié)助排查的GC案例中幾乎最終都是代碼的問題，比較令人的滿意的一個(gè)系統(tǒng)運(yùn)行的場(chǎng)景其實(shí)是每次Ygc都能很好的消化掉垃圾對(duì)象，畢竟G1垃圾收集器的默認(rèn)參數(shù)又少、又不錯(cuò)。
開始
(如上圖)我們從一個(gè)正常來說服務(wù)調(diào)用的鏈路說起：
從鏈路追蹤來看，上游應(yīng)用發(fā)送請(qǐng)求的時(shí)間和下游開始處理請(qǐng)求的時(shí)間應(yīng)該相差無幾。但是，一個(gè)rpc過程拋開業(yè)務(wù)邏輯中間需要哪些過程呢?
(此圖從網(wǎng)上copy，如有抄襲嫌疑，請(qǐng)聯(lián)系我刪除圖片狗頭保命)
可以看到，有序列化，網(wǎng)絡(luò)傳輸?shù)鹊?。那一般接口超時(shí)會(huì)有哪些因素引起呢?
窮舉法：網(wǎng)絡(luò)問題、服務(wù)硬件問題、GC問題等
歷史重現(xiàn)
X月XX日，線上查詢服務(wù)又一次發(fā)生了抖動(dòng)，于是公司內(nèi)某張姓大佬過來問我,對(duì)話如下：
張大佬：雞哥，請(qǐng)教個(gè)問題
雞哥：你說說看，我應(yīng)該不會(huì)(圖片)
張大佬：G1中加了-XX:+ParallelRefProcEnabled參數(shù)之后，GC耗時(shí)還是會(huì)很長(zhǎng)，導(dǎo)致一波超時(shí)，你知道什么情況么?
雞哥：你確定么?
我們來分析下這個(gè)參數(shù)，按道理來說這個(gè)參數(shù)(-XX:+ParallelRefProcEnabled)的含義是：盡可能啟用并行引用處理
那好，
我們探索下他為什么要加這個(gè)參數(shù)?是出現(xiàn)了什么現(xiàn)象讓他要加這個(gè)參數(shù)?
原來是張姓大佬通過gclog發(fā)現(xiàn)每次GC的【ref proc】階段耗時(shí)比較長(zhǎng)，于是他從網(wǎng)上搜索到了這個(gè)參數(shù)之后就加上試了一下
現(xiàn)象
如上圖我們可以發(fā)現(xiàn)在gc過程中 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說起，我們都知道，Ygc就是對(duì)象填滿Eden區(qū)然后觸發(fā)Ygc，而正常來說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ì)有疑問?那我為了減少STW的時(shí)間，我就去降低MaxGCPauseMillis
此言差矣!!!!
MaxGCPauseMillis 越小，年輕代也越小，從而導(dǎo)致有很多短生命周期的對(duì)象被過早晉升到老年代。而老年代你們都懂的，標(biāo)記清理過程比年輕代要復(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問題處理群
實(shí)驗(yàn)了
三組對(duì)比參數(shù)
未調(diào)試:沒有加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還沒有觸發(fā)，所以耗時(shí)未知
我們可以基本上看到很明顯的問題就是通過加入(-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完全沒辦法支撐，還是會(huì)帶來大量抖動(dòng)，但是現(xiàn)有的gclog不夠觀察到本質(zhì)，于是我推薦了如下參數(shù)，觀測(cè)更具體的信息
-XX:+PrintReferenceGC
第二次現(xiàn)象
終于在X月X號(hào)，終于觸發(fā)了一次Mixedgc，日志也出來了(如下)
第二次處理
我們可以看到Softreference和FinalReference 占了兩個(gè)大頭，一個(gè)是132ms，一個(gè)255ms
其實(shí)問題幾乎就已經(jīng)快壓縮到最后了，此時(shí)可以看到Application stop 621ms
第三次現(xiàn)象
于是，問題定位到了就可以著手去解決了!
因?yàn)檐浺么蠹叶贾?，?nèi)存不足的時(shí)候才會(huì)去收集，所以項(xiàng)目中生成的軟引用對(duì)象太多的話，會(huì)在gc過程中產(chǎn)生較大的處理壓力
我們這次加上了 -XX:SoftRefLRUPolicyMSPerMB=0
官方解釋：Soft reference在虛擬機(jī)中比在客戶集中存活的更長(zhǎng)一些。其清除頻率可以用命令行參數(shù) -XX:SoftRefLRUPolicyMSPerMB=
第三次結(jié)果
結(jié)果是什么?
我們可以看到的現(xiàn)象是 soft引用和final引用在每次Ygc過程中都被收集掉一部分，且數(shù)量比之前大一倍
而finalReference的疑問是什么呢?
因?yàn)樵趈ava8的SocketServiceImpl里實(shí)現(xiàn)了Object的finalize方法，為了防止socket鏈接忘了釋放資源，而進(jìn)行幫助釋放
當(dāng)有大量短鏈接未來得及釋放，會(huì)導(dǎo)致Finalizer對(duì)象過多，引起一開始我們看到的現(xiàn)象，所以猜測(cè)ES使用的OKHTTP的調(diào)用方式，但是無法dump，所以無從考證
但因?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á)開始，到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í)不一定，軟引用的回收是需要一定條件的我們看官方文檔怎么說
clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB
clock：上次GC的時(shí)間戳
timestamp：表示最近一次讀取軟引用對(duì)象的時(shí)間戳
這兩者的差值表示該軟引用對(duì)象多久沒被使用了，差值越大，軟引用對(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)的，如下我說的
例子：假設(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天之后，聽著張姓大佬一陣激動(dòng)的叫喊
發(fā)現(xiàn)mixedgc已經(jīng)穩(wěn)定到85ms左右
小插曲
1.為什么軟引用收集參數(shù)【SoftRefLRUPolicyMSPerMB】沒有在jvm中默認(rèn)打開?
答：因?yàn)檐浺玫奶匦蕴貏e適合做Cache，設(shè)計(jì)者目的就是想讓cache常駐內(nèi)存，所以要到內(nèi)存不夠的時(shí)候才去觸發(fā)收集
2.是否要引用ZGC?
中間有人給張姓大佬推薦了ZGC,于是我掏出了這種圖，JDK11開始有的，也是2018年9月左右發(fā)布，
第一，可以嘗試，但是這算是屏蔽了問題，而走捷徑;
第二，沒有人完全能hold住，出了問題誰來負(fù)責(zé)和修復(fù)?
GC調(diào)優(yōu)的幾個(gè)核心要素
一.要有信心
二.不斷壓縮問題到死角
三.多組參數(shù)實(shí)驗(yàn)對(duì)比
畢竟沒有兼容所有場(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，通過查看所有根對(duì)象以及年輕代分區(qū)的RSet，如果確定RSet中巨型對(duì)象沒有任何引用，該對(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í)，無法找到可用的空閑分區(qū)
從老年代分區(qū)轉(zhuǎn)移存活對(duì)象時(shí)，無法找到可用的空閑分區(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]
