[[420555]]

本文轉載自微信公眾號「再見伐木機」，作者再見伐木機。轉載本文請聯(lián)系再見伐木機公眾號。

緣起

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

插曲

這里要糾正一個很多人的誤解，為什么G1老年代的收集叫做mixedGC?

首先G1的進行老年代垃圾回收的時候不一定是全部的老年代，一般是部分的old region，然后因為老年的收集是可以和young gc同時進行的，所以叫mixedgc。

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

開始

(如上圖)我們從一個正常來說服務調用的鏈路說起：

從鏈路追蹤來看，上游應用發(fā)送請求的時間和下游開始處理請求的時間應該相差無幾。但是，一個rpc過程拋開業(yè)務邏輯中間需要哪些過程呢?

(此圖從網(wǎng)上copy，如有抄襲嫌疑，請聯(lián)系我刪除圖片狗頭保命)

可以看到，有序列化，網(wǎng)絡傳輸?shù)鹊取Ｄ且话憬涌诔瑫r會有哪些因素引起呢?

窮舉法：網(wǎng)絡問題、服務硬件問題、GC問題等

歷史重現(xiàn)

X月XX日，線上查詢服務又一次發(fā)生了抖動，于是公司內某張姓大佬過來問我,對話如下：

張大佬：雞哥，請教個問題

雞哥：你說說看，我應該不會(圖片)

張大佬：G1中加了-XX:+ParallelRefProcEnabled參數(shù)之后，GC耗時還是會很長，導致一波超時，你知道什么情況么?

雞哥：你確定么?

我們來分析下這個參數(shù)，按道理來說這個參數(shù)(-XX:+ParallelRefProcEnabled)的含義是：盡可能啟用并行引用處理

那好，

我們探索下他為什么要加這個參數(shù)?是出現(xiàn)了什么現(xiàn)象讓他要加這個參數(shù)?

原來是張姓大佬通過gclog發(fā)現(xiàn)每次GC的【ref proc】階段耗時比較長，于是他從網(wǎng)上搜索到了這個參數(shù)之后就加上試了一下

現(xiàn)象

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

那

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

其實是對各種軟弱虛引用等的處理

圖中ref-proc 0.7034259 secs 就是處理 soft、weak、phantom、final、JNI 等等引用的時間

Oracle官方文檔如下描述：

其實是在G1的remark階段，對上述的引用根據(jù)其特定類型更新所指對象

額外分析

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

• -XX:MaxGCPauseMillis GC 最大停頓時間，默認 200ms 這個參數(shù)會影響到Ygc的STW時間，為什么呢?我們思考一下， MaxGCPauseMillis 時間越小，給STW時間也就越小，年輕代大概率就越小;反之 MaxGCPauseMillis 時間越大，給STW時間也就越大，年輕代大概率就會越大。此時是不是有人會有疑問?那我為了減少STW的時間，我就去降低MaxGCPauseMillis

此言差矣!!!!

MaxGCPauseMillis 越小，年輕代也越小，從而導致有很多短生命周期的對象被過早晉升到老年代。而老年代你們都懂的，標記清理過程比年輕代要復雜的多，整體效率也低，就導致雖然GC停滯時間下降了，但GC次數(shù)可能增多，整體吞吐量下降的情況。并且GC次數(shù)增多也會導致對CPU資源的占用增加，跟業(yè)務線程一起爭搶CPU

第一次處理

然后當天晚點時間，我被拉進一個三人組成的GC問題處理群

實驗了

三組對比參數(shù)

未調試:沒有加ParallelRefProcEnabled，年輕代自動分配了17g，Ygc(40ms)，mixedgc (500ms)

調試1:-XX:+ParallelRefProcEnabled，年輕代自動分配了2g，Ygc(50ms)，Ygc次數(shù)增加，mixedgc(200ms)

調試2:-XX:+ParallelRefProcEnabled和-XX:ParallelgCThreads=8，年輕代17g，Ygc(40ms)，Ygc次數(shù)與未調試的情況差不多，mixedgc還沒有觸發(fā)，所以耗時未知

我們可以基本上看到很明顯的問題就是通過加入(-XX:+ParallelRefProcEnabled)

現(xiàn)象：

總結一

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

第二次處理

當然300ms完全沒辦法支撐，還是會帶來大量抖動，但是現(xiàn)有的gclog不夠觀察到本質，于是我推薦了如下參數(shù)，觀測更具體的信息

-XX:+PrintReferenceGC

第二次現(xiàn)象

終于在X月X號，終于觸發(fā)了一次Mixedgc，日志也出來了(如下)

第二次處理

我們可以看到Softreference和FinalReference 占了兩個大頭，一個是132ms，一個255ms

其實問題幾乎就已經(jīng)快壓縮到最后了，此時可以看到Application stop 621ms

第三次現(xiàn)象

于是，問題定位到了就可以著手去解決了!

因為軟引用大家都知道，內存不足的時候才會去收集，所以項目中生成的軟引用對象太多的話，會在gc過程中產(chǎn)生較大的處理壓力

我們這次加上了 -XX:SoftRefLRUPolicyMSPerMB=0

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

第三次結果

結果是什么?

我們可以看到的現(xiàn)象是 soft引用和final引用在每次Ygc過程中都被收集掉一部分，且數(shù)量比之前大一倍

而finalReference的疑問是什么呢?

因為在java8的SocketServiceImpl里實現(xiàn)了Object的finalize方法，為了防止socket鏈接忘了釋放資源，而進行幫助釋放

當有大量短鏈接未來得及釋放，會導致Finalizer對象過多，引起一開始我們看到的現(xiàn)象，所以猜測ES使用的OKHTTP的調用方式，但是無法dump，所以無從考證

但因為已經(jīng)在每次Ygc中進行收集了，其實也算是達到預期，但是不是很完美。

當然好像JDK9中的AbstractPlainSocketImpl已經(jīng)不再復寫finalize方法了，因為finallize() 方法是Object類的方法, 用于在類被GC回收時 做一些處理操作, 但是JVM并不能保證finalize() 方法一定被執(zhí)行,由finalize()方法的調用時機具有不確定性，從一個對象變得不可到達開始，到finalize()方法被執(zhí)行，所花費的時間這段時間是任意長的。我們并不能依賴finalize()方法能及時的回收占用的資源，可能出現(xiàn)的情況是在我們耗盡資源之前，gc卻仍未觸發(fā)，因而通常的做法是提供顯示的close()方法供客戶端手動調用

小插曲

不少人的認知是soft引用會在內存不足時候回收?其實不一定，軟引用的回收是需要一定條件的我們看官方文檔怎么說

clock - timestamp <= freespace * SoftRefLRUPolicyMSPerMB

clock：上次GC的時間戳

timestamp：表示最近一次讀取軟引用對象的時間戳

這兩者的差值表示該軟引用對象多久沒被使用了，差值越大，軟引用對象價值越低，負數(shù)則表示軟引用對象剛剛被使用

freespace是空閑空間大小，SoftRefLRUPolicyMSPerMB表示每一MB的空閑內存空間可以允許軟引用對象存活多久，這也就間接的解釋了，為什么空間不夠用，空閑空間越小，軟應用對象就會被回收，因為它的存活時間會隨著空閑空間的減小而遞減。可以把 【freespace * SoftRefLRUPolicyMSPerMB】理解為忍耐度，對軟應用對象的忍耐程度。

等待

其實從gclog和現(xiàn)象之中大概已經(jīng)猜測到基本上已經(jīng)算是成功了，但是呢，加上這個參數(shù)【SoftRefLRUPolicyMSPerMB】也是有風險的，如下我說的

例子：假設程序中有很多反射創(chuàng)建類的操作，因為反射創(chuàng)建的類本身的Class對象都是被SoftReference軟引用的，加上了如上的參數(shù)，軟引用就會被盡快的釋放掉，所以就會產(chǎn)生，反射創(chuàng)建大量類->剛創(chuàng)建完GC回收掉很多->反射執(zhí)行繼續(xù)創(chuàng)建大量類，最終導致Metaspace區(qū)域被打滿->導致FullGC

結果

等待了4天之后，聽著張姓大佬一陣激動的叫喊

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

小插曲

1.為什么軟引用收集參數(shù)【SoftRefLRUPolicyMSPerMB】沒有在jvm中默認打開?

答：因為軟引用的特性特別適合做Cache，設計者目的就是想讓cache常駐內存，所以要到內存不夠的時候才去觸發(fā)收集

2.是否要引用ZGC?

中間有人給張姓大佬推薦了ZGC,于是我掏出了這種圖，JDK11開始有的，也是2018年9月左右發(fā)布，

第一，可以嘗試，但是這算是屏蔽了問題，而走捷徑;

第二，沒有人完全能hold住，出了問題誰來負責和修復?

GC調優(yōu)的幾個核心要素

一.要有信心

二.不斷壓縮問題到死角

三.多組參數(shù)實驗對比

畢竟沒有兼容所有場景的參數(shù)，只有符合自己業(yè)務場景的參數(shù)調優(yōu)

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

[GC pause (G1 Evacuation Pause) (young), 0.0022483 secs]

young -> 年輕代 Evacuation-> 復制存活對象

[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，檢測從年輕代指向老年代的對象

[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] # 轉移和回收，拷貝存活的對象到survivor/old區(qū)域

[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # 完成上述任務后，如果任務隊列已空，則工作線程會發(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外部的并行活動，該部分并非GC的活動，而是JVM的活動導致占用了GC暫停時間(例如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] # 串行任務，根據(jù)轉移對象更新代碼根

[Code Root Purge: 0.0 ms] #串行任務， 代碼根清理

[Clear CT: 0.5 ms] #串行任務，清除全局卡片 Card Table 標記

[Other: 0.8 ms]

[Choose CSet: 0.0 ms] # 選擇下次收集集合 CSet

[Ref Proc: 0.4 ms] # 引用處理 Ref Proc，處理軟引用、弱引用、虛引用、final引用、JNI引用

[Ref Enq: 0.0 ms] # 引用排隊 Ref Enq

[Redirty Cards: 0.3 ms] # 卡片重新臟化 Redirty Cards：重新臟化卡片

[Humongous Register: 0.0 ms]

[Humongous Reclaim: 0.0 ms] # 回收空閑巨型分區(qū) Humongous Reclaim，通過查看所有根對象以及年輕代分區(qū)的RSet，如果確定RSet中巨型對象沒有任何引用，該對象分區(qū)會被回收。

[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ū)拷貝存活對象時，無法找到可用的空閑分區(qū)

從老年代分區(qū)轉移存活對象時，無法找到可用的空閑分區(qū) 這兩種情況之一導致的 YGC

[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0916534 secs]

并發(fā)標記周期 Concurrent Marking Cycle 中的 根分區(qū)掃描階段，被 YGC中斷

 

[GC pause (G1 Evacuation Pause) (young)[GC concurrent-root-region-scan-end, 0.0007157 secs]