一個大對象引發的血案，GC的踩坑實錄

時間 2019-11-13

標籤個大對象引發血案實錄欄目 Java 简体版

原文原文鏈接

背景：java

問題：json

有個渠道支付服務，負責與全部支付相關服務進行交互，包括渠道下單支付，渠道成功通知，渠道的對帳等tomcat

服務4臺機，平時跑的都很穩定，經過thrift進行對外提供服務，且平時並未發現訪問超時的狀況，已經平穩在線上跑了1年多了，沒出現過超時問題。併發

但最近發現，天天到了晚上凌晨2點開始大量服務訪問超時，且定位到每次都是搶到對帳任務的那臺服務出現問題。app

解決：ide

後經過監控和打印GC日誌發現，出現問題機器服務的Major GC頻率增長，應該是內存問題。性能

故把對帳程序拆出後單獨部署後，再沒出現服務訪問超時狀況。測試

分析，對帳時，由於要撈出當天支付數據到內存進行對帳（隨着業務發展訂單開始猛增）故觸發了GC。其實增長分批limit固然也能夠解決。固然像這種對帳，訂單多了後最好應該是單獨分拆模塊，進行離線處理了。url

這是最近第二次踩到GC的坑了，第一次是每次訪問給每一個線程分配的內存過多，併發上來後性能嚴重下降，致使WEB超時，有必要總結下了spa

重現下：

死磕重現下，

模擬業務部分，假使每一個業務須要500ms返回，代碼以下：

/**
 * 模擬當系統中使用大對象時,對JVM形成的影響
 * 
 * @author 包子(何錦彬). 2017.01.07
 * @QQ 277803242
 */
@WebServlet("/Test")
public class Test extends HttpServlet {
    private static final long serialVersionUID = 1L;
    private Logger logger = Logger.getLogger(Test.class.getName());

    protected void doGet(HttpServletRequest request, HttpServletResponse response)
            throws ServletException, IOException {
        long startTime = System.currentTimeMillis();
        // deal
        try {
            // 模擬業務花費時間
            Thread.sleep(500);
        } catch (InterruptedException e) {
        }
        long costTime = (System.currentTimeMillis() - startTime);
        // 接口1秒timeout,打印出日誌
        if (costTime > 1000) {
            logger.warning("cost time:" + costTime);
        }
        Writer out = response.getWriter();
        out.append("ok");
    }
}

放入tomcat，加入垃圾回收方式和堆內存大小，打印垃圾回收日誌

JAVA_OPTS="-Xmx1200m -Xms1200m -Xmn200m -Xss228k -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+PrintGCDetails"

用jmeter壓測1分鐘後，發現正常，每次返回均在500毫秒左右，日誌裏也沒有出現訪問超時。

加入模擬對帳部分代碼，1分鐘後對帳開啓，持續提供服務，爲了讓它觸發GC，模擬加載了1G的待對帳數據，（固然，在生產環境裏只是一個大對象，但OU區原本就有東西了）

/**
 * 模擬定時對帳， 模擬來了個大對象對帳
 * 
 * @author 包子(何錦彬). 2017.01.07
 * @QQ 277803242
 */
@WebServlet(name = "init", loadOnStartup = 1, description = "init", urlPatterns = "/task")
public class BigObject extends HttpServlet {
    class ReconciliationTask extends TimerTask {

        @Override
        public void run() {
            logger.warning("a big object have commit，exp: reconciliation");
            byte[] bigObject = new byte[1024 * 1024 * 500];// 年老代 500M,剛恰好達到年老代的50%，不斷觸發GC
            try {
                Thread.sleep(60 * 1000);
            } catch (InterruptedException e) {
                // TODO Auto-generated catch block
                e.printStackTrace();
            }
        }

    }

    private static final long serialVersionUID = 1L;
    private Logger logger = Logger.getLogger(Test.class.getName());

    @Override
    public void init() throws ServletException {
        Timer timer = new Timer();
        timer.schedule(new ReconciliationTask(), 60 * 1000);// 1分鐘後模擬開始對帳任務
        logger.log(Level.INFO, "task have registered");
        super.init();
    }
}

和上面同樣的參數啓動tomcat， 1G內存，CMS回收，用jmeter壓測1分鐘後，發現 Major GC大量發生，截取一週期的Major GC日誌以下：

GC [1 CMS-initial-mark: 1048576K(1740800K)] 1051853K(1832960K), 0.0042630 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark: 0.023/0.023 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
[CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
 CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.222/5.020 secs] [Times: user=0.20 sys=0.03, real=5.02 secs] 
[GC[YG occupancy: 3277 K (92160 K)][Rescan (parallel) , 0.0067540 secs][weak refs processing, 0.0000400 secs][scrub string table, 0.0004160 secs] [1 CMS-remark: 1048576K(1740800K)] 1051853K(1832960K), 0.0076820 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-reset: 0.014/0.014 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]

此時的用jstat查看的話狀況以下：

S0C      S1C     S0U    S1U      EC       EU        OC         OU       PC     PU    YGC    YGCT    FGC    FGCT     GCT 
20480.0 20480.0  0.0   17257.9 163840.0 93241.7  1024000.0   512000.0  29356.0 17612.0      1    0.032   5      0.159    0.191
20480.0 20480.0  0.0   17257.9 163840.0 93241.8  1024000.0   512000.0  29356.0 17612.0      1    0.032   5      0.159    0.191
20480.0 20480.0  0.0   17257.9 163840.0 93241.9  1024000.0   512000.0  29356.0 17612.0      1    0.032   5      0.159    0.191
20480.0 20480.0  0.0   17257.9 163840.0 93242.0  1024000.0   512000.0  29356.0 17612.0      1    0.032   5      0.159    0.191
20480.0 20480.0  0.0   17257.9 163840.0 93242.0  1024000.0   512000.0  29356.0 17612.0      1    0.032   5      0.159    0.191
20480.0 20480.0  0.0   17257.9 163840.0 93242.1  1024000.0   512000.0  29356.0 17612.0      1    0.032   6      0.183    0.214

致使結果，大量接口訪問超時，截取一部分日誌以下：

13-Jan-2017 01:26:43.692 WARNING [http-nio-8080-exec-78] org.hjb.memory.Test.doGet cost time:1482
13-Jan-2017 01:26:43.693 WARNING [http-nio-8080-exec-28] org.hjb.memory.Test.doGet cost time:1434
13-Jan-2017 01:26:43.694 WARNING [http-nio-8080-exec-23] org.hjb.memory.Test.doGet cost time:1492
13-Jan-2017 01:26:43.699 WARNING [http-nio-8080-exec-85] org.hjb.memory.Test.doGet cost time:1514
13-Jan-2017 01:26:43.700 WARNING [http-nio-8080-exec-97] org.hjb.memory.Test.doGet cost time:1515
13-Jan-2017 01:26:43.701 WARNING [http-nio-8080-exec-83] org.hjb.memory.Test.doGet cost time:1517
13-Jan-2017 01:26:43.704 WARNING [http-nio-8080-exec-87] org.hjb.memory.Test.doGet cost time:1547
13-Jan-2017 01:26:43.705 WARNING [http-nio-8080-exec-41] org.hjb.memory.Test.doGet cost time:1548
13-Jan-2017 01:26:43.707 WARNING [http-nio-8080-exec-35] org.hjb.memory.Test.doGet cost time:1552
13-Jan-2017 01:26:43.707 WARNING [http-nio-8080-exec-26] org.hjb.memory.Test.doGet cost time:1557
13-Jan-2017 01:26:43.709 WARNING [http-nio-8080-exec-101] org.hjb.memory.Test.doGet cost time:1559
13-Jan-2017 01:26:43.690 WARNING [http-nio-8080-exec-42] org.hjb.memory.Test.doGet cost time:1482
13-Jan-2017 01:26:43.716 WARNING [http-nio-8080-exec-80] org.hjb.memory.Test.doGet cost time:1578
13-Jan-2017 01:26:43.720 WARNING [http-nio-8080-exec-3] org.hjb.memory.Test.doGet cost time:1583
13-Jan-2017 01:26:43.690 WARNING [http-nio-8080-exec-22] org.hjb.memory.Test.doGet cost time:1420
13-Jan-2017 01:26:43.690 WARNING [http-nio-8080-exec-59] org.hjb.memory.Test.doGet cost time:1295
13-Jan-2017 01:26:43.689 WARNING [http-nio-8080-exec-51] org.hjb.memory.Test.doGet cost time:1294
13-Jan-2017 01:26:43.727 WARNING [http-nio-8080-exec-79] org.hjb.memory.Test.doGet cost time:1559
13-Jan-2017 01:26:43.731 WARNING [http-nio-8080-exec-63] org.hjb.memory.Test.doGet cost time:1630
13-Jan-2017 01:26:43.687 WARNING [http-nio-8080-exec-77] org.hjb.memory.Test.doGet cost time:1429
13-Jan-2017 01:26:43.686 WARNING [http-nio-8080-exec-95] org.hjb.memory.Test.doGet cost time:1371
13-Jan-2017 01:26:43.737 WARNING [http-nio-8080-exec-8] org.hjb.memory.Test.doGet cost time:1595
13-Jan-2017 01:26:43.686 WARNING [http-nio-8080-exec-84] org.hjb.memory.Test.doGet cost time:1429
13-Jan-2017 01:26:43.686 WARNING [http-nio-8080-exec-92] org.hjb.memory.Test.doGet cost time:1295
13-Jan-2017 01:26:43.678 WARNING [http-nio-8080-exec-20] org.hjb.memory.Test.doGet cost time:1390

上面是HTTP的，thrift訪問其實也是同樣的。

總結：

大對象使用會嚴重影響到服務的性能質量，時刻觀察GC的發生。服務的穩定性很GC關係很大

踩過GC的幾個坑

1，內存不夠用，JVM用到SWAP

若是每次GC時間不合理時，如： FGC=10，FGCT=1，基本能夠確定是用到了SWAP內存區了 (固然也和你內存大小有關，指通常系統內存在8G附近)

2，用到大對象，致使頻繁FGC( FULLGC和 Major GC 對性能都有嚴重影響)

看不少資料上說是60%觸發Major GC，但經測試發現，在OU到了50%時開始不斷觸發Major GC

4，YGC變更愈來愈久，如用到了string.intern()方法. (好比在 fastjson 中有用到)，

緣由： string.intern() 往常量池加如數據。而ROOT GC時，須要掃描全部常量做爲根節點，當常量池越大量增長時，掃描的數據時間增長

5，GC裏面出現有

Concurrent mode failed

緣由：因爲GC在CMS時，往OU區放入對象，而後不可用。

發現大量這種現象，

1，增長OLD區的內存壓縮參數， UseCMSCompactAtFullCollection 或 CMSFullGCsBeforeCompaction

2，建議調大年輕代內存調大，或增長OLD區的回收頻率

Prommotion failed

1. 年輕代對象晉升失敗，當啓用了擔保分配，每次晉升會檢查年老代的內存是否夠大於年輕代平均晉升對象的大小，若是小於將會進行FULLGC，日誌會顯示Prommotion faile引發fullGC

2, JDK6後默認都開啓了擔保分配

再解釋下GC的幾個名詞

有幾個誤區：

FULL GC ， Major GC ， Minor GC

Minor GC 就是年輕代清理，這個好理解

FULL GC 指整個永久代（或G1的Metaspace代）的和堆內存，堆外內存一塊兒清理. 在GC日誌裏的FULL GC指的是這個

Major GC 年老代的清理，在jstat -gc 裏的FGC只是指這個，只是年老代的GC而已

詳細：https://plumbr.eu/handbook/garbage-collection-in-java

誤區：jstat 的FGC，它統計的僅僅是STW的次數，即兩個init-mark和 remark的階段

問題：

引發FULL GC的緣由有哪些呢？

一、System.gc()方法的調用
二、老年代代空間不足
三、永生區空間不足
四、CMS GC時出現，如GC日誌中找到promotion failed（晉升失敗）和concurrent mode failure（回收時有對象要分配）
五、統計獲得的Minor GC晉升到舊生代的平均大小大於老年代的剩餘空間
六、空間碎片太多，堆中分配很大的對象（若是如此，建議每次FULLGC後開啓壓縮）

如何查看GC 發生的緣由呢？

目前能想到的，最簡單是 jstat -gccause

感謝各位網友的疑問，說明下：

這裏對帳其實算曆史緣由，之前系統量不大時是放在了支付模塊實際上是沒問題，後面進行了分拆，

1，這種跑批的任務不該該和服務放一塊後面，應該是單獨的模塊

2. 對於對帳，個人解決是後面放mongoDB，而後拿出來進行對帳，徹底是個離線處理的過程了

3，感謝各位的疑問。其實不必定是對帳，不少系統會把跑批和服務放一塊，若是跑批涉及到把數據load到內存的話，必定要注意垃圾回收了。否則容易觸發CMS的GC。並且通過我測試，每次到了老年代的50%就會不斷觸發GC，若是跑批任務持續時間比較久，不釋放對象，將不停的Major GC。

有個疑問

上面例子中，我加上 +XX:CMSInitiatingOccupancyFraction=80 後，仍是會不停的Major GC( 例子中只佔50%)，待解答

持續更新留言問題，解答疑問

歡迎關注個人公衆號，專一重現各類線上的BUG