一次年輕代GC長暫停問題的解決與思考

時間  2020-09-29
標籤 一次 年輕 暫停 問題 解決 思考 欄目 Java 简体版
原文   原文鏈接

問題描述

公司某規則引擎系統，在每次發版啓動會手動預熱，預熱完成當流量切進來以後會偶發的出現一次長達1-2秒的年輕代GC（流量並不大，而且LB下的每一臺服務都會出現該狀況）java

在此次長暫停以後，每一次的年輕代GC暫停時間又都恢復在20-100ms之內算法

2s雖然看起來不長，可是對比規則引擎每次10ms左右的響應時間來講，仍是不能夠接受的；而且因爲該規則引擎響應超時，還會致使出單超時失敗jvm

問題分析

在分析該系統GC日誌後發現，2s暫停發生在Young GC階段，並且每次發生長暫停的Young GC都會伴隨着新生代對象的晉升(Promotion)測試

核心JVM參數（Oracle JDK7）this

-Xms10G 
-Xmx10G 
-XX:NewSize=4G 
-XX:PermSize=1g 
-XX:MaxPermSize=4g 
-XX:+UseConcMarkSweepGC

啓動後第一次年輕代GC日誌spa

2020-04-23T16:28:31.108+0800: [GC2020-04-23T16:28:31.108+0800: [ParNew2020-04-23T16:28:31.229+0800: [SoftReference, 0 refs, 0.0000950 secs]2020-04-23T16:28:31.229+0800: [WeakReference, 1156 refs, 0.0001040 secs]2020-04-23T16:28:31.229+0800: [FinalReference, 10410 refs, 0.0103720 secs]2020-04-23T16:28:31.240+0800: [PhantomReference, 286 refs, 2 refs, 0.0129420 secs]2020-04-23T16:28:31.253+0800: [JNI Weak Reference, 0.0000000 secs]
Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age   1:  315529928 bytes,  315529928 total
- age   2:   40956656 bytes,  356486584 total
- age   3:    8408040 bytes,  364894624 total
: 3544342K->374555K(3774912K), 0.1444710 secs] 3544342K->374555K(10066368K), 0.1446290 secs] [Times: user=1.46 sys=0.09, real=0.15 secs]

長暫停年輕代GC日誌.net

2020-04-23T17:18:28.514+0800: [GC2020-04-23T17:18:28.514+0800: [ParNew2020-04-23T17:18:29.975+0800: [SoftReference, 0 refs, 0.0000660 secs]2020-04-23T17:18:29.975+0800: [WeakReference, 1224 refs, 0.0001400 secs]2020-04-23T17:18:29.975+0800: [FinalReference, 8898 refs, 0.0149670 secs]2020-04-23T17:18:29.990+0800: [PhantomReference, 600 refs, 1 refs, 0.0344300 secs]2020-04-23T17:18:30.025+0800: [JNI Weak Reference, 0.0000210 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age   1:   79203576 bytes,   79203576 total
: 3730075K->304371K(3774912K), 1.5114000 secs] 3730075K->676858K(10066368K), 1.5114870 secs] [Times: user=6.32 sys=0.58, real=1.51 secs]

從這個長暫停的GC日誌來看，是發生了晉升的，在Young GC後，有363M+的對象晉升到了老年代，這個晉升操做因該就是耗時緣由（ps: 檢查過safepoint緣由，不存在異常）指針

因爲日誌參數中沒有配置-XX:+PrintHeapAtGC參數，這裏是手動計算的晉升大小：日誌

年輕代年輕變化 - 全堆容量變化 = 晉升大小
(304371K - 3730075K) - (676858K - 3730075K) = 372487K(363M)code

下一次年輕代GC日誌

2020-04-23T17:23:39.749+0800: [GC2020-04-23T17:23:39.749+0800: [ParNew2020-04-23T17:23:39.774+0800: [SoftReference, 0 refs, 0.0000500 secs]2020-04-23T17:23:39.774+0800: [WeakReference, 3165 refs, 0.0002720 secs]2020-04-23T17:23:39.774+0800: [FinalReference, 3520 refs, 0.0021520 secs]2020-04-23T17:23:39.776+0800: [PhantomReference, 150 refs, 1 refs, 0.0051910 secs]2020-04-23T17:23:39.782+0800: [JNI Weak Reference, 0.0000100 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age   1:   17076040 bytes,   17076040 total
- age   2:   40832336 bytes,   57908376 total
: 3659891K->90428K(3774912K), 0.0321300 secs] 4032378K->462914K(10066368K), 0.0322210 secs] [Times: user=0.30 sys=0.00, real=0.03 secs] 
 

乍一看其實沒什麼問題，仔細想一想發現了一些不正常，爲何程序剛啓動第二次gc就發生了晉升呢

這裏應該是動態年齡斷定致使的，GC中晉升年齡閾值並非固定的15，而是jvm每次gc後動態計算的

年輕代晉升機制

爲了能更好地適應不一樣程序的內存情況，虛擬機並非永遠地要求對象的年齡必須達到了MaxTenuringThreshold才能晉升老年代，若是在Survivor空間中相同年齡全部對象大小的總和大於Survivor空間的一半，年齡大於或等於該年齡的對象就能夠直接進入老年代，無須等到MaxTenuringThreshold中要求的年齡
《深刻理解Java虛擬機》一書中提到，對象晉升年齡的閾值是動態斷定的。

不過經查閱其餘資料和驗證後，發現此處和《深刻理解Java虛擬機》解釋的有些出入（或者是書上解釋的不夠清楚）

其實就是按年齡給對象分組，取total（累加值，小於等與當前年齡的對象總大小）最大的年齡分組，若是該分組的total大於survivor的一半，就將晉升年齡閾值更新爲該分組的年齡

注意：不是是超過survivor一半就晉升，超過survivor一半隻會從新設置晉升閾值（threshold），在下一次GC纔會使用該新閾值

3544342K->374555K(3774912K), 0.1444710 secs] 年輕代

3544342K->374555K(10066368K), 0.1446290 secs] 全堆
 

從上面第一次的GC日誌也能夠證實這個結論，在此次GC中全堆的內存變化和年輕代內存變化是相等的，因此並無發生對象的晉升

就像上面的日誌中，第一次GC只是將threshold設置爲1，由於此時survivor一半爲214728704 bytes，而年齡爲1的對象總和有315529928 bytes，超過了Desired survivor size，因此在本次GC後將threshold設置爲年齡爲1的對象年齡1

這裏更新了對象晉升年齡閾值爲1

Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age   1:  315529928 bytes,  315529928 total
- age   2:   40956656 bytes,  356486584 total
- age   3:    8408040 bytes,  364894624 total

這裏順便解釋下這個年齡分佈的輸出內容：

- age 1: 315529928 bytes, 315529928 total
  • age 1表示年齡爲1的對象分組，315529928 bytes表示年齡爲1的對象佔用內存大小

315529928 total這個是一個累加值，表示小於等於當前分組年齡的對象總大小。先把對象按年齡分組，age 1的分組total爲age 1總大小（前面的xxx bytes），age 2的分組total爲age 1 + age 2總大小，age n的分組total爲age 1 + age 2 + ... +age n的總大小，累加規則以下圖所示

 

image.png

當total最大的分組的total值超過了survivor/2時，就會更新晉升閾值

在第二次年輕代GC「長暫停年輕代GC日誌」中，因爲新的晉升年齡閾值爲1，因此那些經歷了一次GC並存活而且如今仍然可達（reachable）的對象們就會發生晉升了

因爲這次GC發生了363M的對象晉升，因此致使了長暫停

思考

JVM中這個「動態對象年齡斷定」真的是合理的嗎？我的認爲機制是好的，能夠更好的適應不一樣程序的內存情況，但不是任何場景都適合，好比在本文中這個剛啓動不就GC的場景下就會有問題

由於在程序剛啓動時，大多數對象年齡都是0或者1，很容易出現年齡爲1的大量存活對象；在這個「動態對象年齡斷定」機制下，就會致使新的晉升閾值被設置爲1，致使這些不應晉升的對象發生了晉升

好比程序在初始化，正在加載各類資源時發生了Young GC，加載邏輯還在執行中，不少新建的對象年齡在此次GC時仍是可達的（reachable）

經歷了此次GC後，這些對象年齡更新爲1，可是因爲「動態對象年齡斷定」機制的影響，晉升年齡閾值更新爲了「最大的對象年齡分組」的年齡，也就是這批剛經歷了一次GC的對象們

在此次GC以後不久，資源初始化完成了，涉及的相關對象有極可能不可達了，可是因爲剛纔晉升年齡閾值被更新爲了1，在下一次正常的Young GC這批年齡爲1的對象會直接發生晉升，提早或者說錯誤的發生了晉升

解決方案

經查閱文檔、資料，發現「動態年齡斷定」這個機制並不能禁用，因此若是想解決這個問題，只有靠「繞過」這個計算規則了

動態年齡的斷定，是根據Survivor空間中相同年齡全部對象大小的總和大於Survivor空間的一半來斷定的，那麼根據這個機制解決也很簡單

因爲咱們足夠了解本身的系統，清楚的知道加載資源所需的大概內存，徹底能夠設定一個大於這些暫時可達的對象總和的數值來做爲survivor的容量

好比上面的日誌中，第一次GC後年齡爲1的對象有315529928 Bytes(300M)，Desired survivor size爲（survivor size /2）214728704 bytes(204M)，那麼survivor就能夠設置爲600M以上。

不過爲了穩妥，仍是將survivor調到800M，這樣desired survivor size就是400M左右，在第一次Young GC後，就不會因年齡爲1的對象總和超過了desired survivor size而致使晉升年齡閾值的更新了，從而也就不會有提早/錯誤晉升而致使的GC長暫停問題

survivor不能夠直接指定大小，不過能夠經過-XX:SurvivorRatio這種調節比例的方式來調節survivor大小

-XX:SurvivorRatio=8

表示兩個Survivor和Edgen區的比，8表示兩個Survivor:Eden=2:8，即一個Survivor佔新生代的1/10。

計算方式爲：

Survivor Size(1) = Young Generation Size / (2+SurvivorRatio)
Eden Size = Young Generation Size / (2+SurvivorRatio) * SurvivorRatio

擴展閱讀

爲何晉升300M比年輕代回收3G還要慢這麼多倍
根據複製算法的特性，複製算法的時間消耗主要取決於存活對象的大小，而不是總空間的大小

好比上面4G的年輕代（實際只有Eden+S0可用），GC時只須要從GC ROOTS開始遍歷對象圖，將可達的對象複製至S1便可，並不須要遍歷整個年輕代

在上面那次長暫停GC日誌中，發生了363M的晉升，300M左右的回收，對比第一次GC基本能夠得出，花費的1.5S基本上都是在晉升操做

那麼爲何晉升操做這麼耗時呢？

這裏沒有深刻研究Oracle JVM實現的年輕代晉升細節，不過晉升涉及跨代複製（其實都年輕代和老年代都是heap，在複製這件事上本質上沒什麼區別，都是memcpy而已，只是須要額外處理的邏輯更多了）
，所需處理的邏輯會更復雜一些，好比指針的更新等操做，更耗時也是能夠理解的，

本地代碼模擬

這裏也附上一段能夠在本地模擬問題的代碼，Oracle JDK7下可直接運行測試

//jdk7.。

import java.io.IOException;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;

public class PromotionTest {
    public static void main(String[] args) throws IOException {
        //模擬初始化資源場景
        List<Object> dataList = new ArrayList<>();
        for (int i = 0; i < 5; i++) {
            dataList.add(new InnerObject());
        }
        //模擬流量進入場景
        for (int i = 0; i < 73; i++) {
            if(i == 72){
                System.out.println("Execute young gc...Adjust promotion threshold to 1");
            }
            new InnerObject();
        }
        System.out.println("Execute full gc...dataList has been promoted to cms old space");
        //這裏注意dataList中的對象在此次Full GC後會進入老年代
        System.gc();
    }
    public static byte[] createData(){
        int dataSize = 1024*1024*4;//4m
        byte[] data = new byte[dataSize];
        for (int j = 0; j < dataSize; j++) {
            data[j] = 1;
        }
        return data;
    }
    static class InnerObject{
        private Object data;

        public InnerObject() {
            this.data = createData();
        }
    }
}
 

jvm options

-server -Xmn400M -XX:SurvivorRatio=9 -Xms1000M -Xmx1000M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime -XX:+UseConcMarkSweepGC

 

 

 

看完三件事❤️

若是你以爲這篇內容對你還蠻有幫助，我想邀請你幫我三個小忙：

  1. 點贊，轉發，有大家的 『點贊和評論』，纔是我創造的動力。

  2. 關注公衆號 『 java爛豬皮 』，不按期分享原創知識。

  3. 同時能夠期待後續文章ing🚀

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程