當(dāng)前位置：首頁 >

一个大对象引起的血案，GC的踩坑实录

發(fā)布時(shí)間：2025/5/22 52 如意码农

生活随笔收集整理的這篇文章主要介紹了一个大对象引起的血案，GC的踩坑实录小編覺得挺不錯(cuò)的,現(xiàn)在分享給大家,幫大家做個(gè)參考.

背景：

問題：

有個(gè)渠道支付服務(wù)，負(fù)責(zé)與所有支付相關(guān)服務(wù)進(jìn)行交互，包括渠道下單支付，渠道成功通知，渠道的對(duì)賬等

服務(wù)4臺(tái)機(jī)，平時(shí)跑的都很穩(wěn)定，通過thrift進(jìn)行對(duì)外提供服務(wù)，且平時(shí)并未發(fā)現(xiàn)訪問超時(shí)的情況，已經(jīng)平穩(wěn)在線上跑了1年多了，沒出現(xiàn)過超時(shí)問題。

但最近發(fā)現(xiàn)，每天到了晚上凌晨2點(diǎn)開始大量服務(wù)訪問超時(shí)，且定位到每次都是搶到對(duì)賬任務(wù)的那臺(tái)服務(wù)出現(xiàn)問題。

解決：

后通過監(jiān)控和打印GC日志發(fā)現(xiàn)，出現(xiàn)問題機(jī)器服務(wù)的Major GC頻率增加，應(yīng)該是內(nèi)存問題。

故把對(duì)賬程序拆出后單獨(dú)部署后，再?zèng)]出現(xiàn)服務(wù)訪問超時(shí)情況。

分析，對(duì)賬時(shí)，因?yàn)橐獡瞥霎?dāng)天支付數(shù)據(jù)到內(nèi)存進(jìn)行對(duì)賬（隨著業(yè)務(wù)發(fā)展訂單開始猛增）故觸發(fā)了GC。其實(shí)增加分批limit當(dāng)然也可以解決

這是最近第二次踩到GC的坑了，第一次是每次訪問給每個(gè)線程分配的內(nèi)存過多，并發(fā)上來后性能嚴(yán)重降低，導(dǎo)致WEB超時(shí)，有必要總結(jié)下了

重現(xiàn)下：

死磕重現(xiàn)下，

模擬業(yè)務(wù)部分，假使每個(gè)業(yè)務(wù)需要500ms返回，代碼如下：

/**

 * 模擬當(dāng)系統(tǒng)中使用大對(duì)象時(shí),對(duì)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 {

            // 模擬業(yè)務(wù)花費(fèi)時(shí)間

            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，加入垃圾回收方式和堆內(nèi)存大小，打印垃圾回收日志

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

用jmeter壓測1分鐘后，發(fā)現(xiàn)正常，每次返回均在500毫秒左右，日志里也沒有出現(xiàn)訪問超時(shí)。

加入模擬對(duì)賬部分代碼，1分鐘后對(duì)賬開啟，持續(xù)提供服務(wù)，為了讓它觸發(fā)GC，模擬加載了1G的待對(duì)賬數(shù)據(jù)，（當(dāng)然，在生產(chǎn)環(huán)境里只是一個(gè)大對(duì)象，但OU區(qū)本來就有東西了）

/**

 * 模擬定時(shí)對(duì)賬， 模擬來了個(gè)大對(duì)象對(duì)賬

 *

 * @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,剛剛好達(dá)到年老代的50%，不斷觸發(fā)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分鐘后模擬開始對(duì)賬任務(wù)

        logger.log(Level.INFO, "task have registered");

        super.init();

    }

}

和上面一樣的參數(shù)啟動(dòng)tomcat， 1G內(nèi)存，CMS回收，用jmeter壓測1分鐘后，發(fā)現(xiàn) Major GC大量發(fā)生，截取一周期的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]

此時(shí)的用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

導(dǎo)致結(jié)果，大量接口訪問超時(shí)，截取一部分日志如下：

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訪問其實(shí)也是一樣的。

總結(jié)：

大對(duì)象使用會(huì)嚴(yán)重影響到服務(wù)的性能質(zhì)量，時(shí)刻觀察GC的發(fā)生。

踩過GC的幾個(gè)坑

1，內(nèi)存不夠用，JVM用到SWAP

如果每次GC時(shí)間不合理時(shí)，如： FGC=10，F(xiàn)GCT=1，基本可以肯定是用到了SWAP內(nèi)存區(qū)了 (當(dāng)然也和你內(nèi)存大小有關(guān)，指一般系統(tǒng)內(nèi)存在8G附近)

2，用到大對(duì)象，導(dǎo)致頻繁FGC( FULLGC和 Major GC 對(duì)性能都有嚴(yán)重影響)

看很多資料上說是60%觸發(fā)Major GC，但經(jīng)測試發(fā)現(xiàn)，在OU到了50%時(shí)開始不斷觸發(fā)Major GC

4，YGC變動(dòng)越來越久，如用到了string.intern()方法. (比如在 fastjson 中有用到)，

原因： string.intern() 往常量池加如數(shù)據(jù)。而ROOT GC時(shí)，需要掃描所有常量作為根節(jié)點(diǎn)，當(dāng)常量池越大量增加時(shí)，掃描的數(shù)據(jù)時(shí)間增加

5，GC里面出現(xiàn)有

Concurrent mode failed

原因：由于GC在CMS時(shí)，往OU區(qū)放入對(duì)象，然后不可用。

發(fā)現(xiàn)大量這種現(xiàn)象，

1，增加OLD區(qū)的內(nèi)存壓縮參數(shù)， UseCMSCompactAtFullCollection 或 CMSFullGCsBeforeCompaction

2，建議調(diào)大年輕代內(nèi)存調(diào)大，或增加OLD區(qū)的回收頻率

Prommotion failed

1. 年輕代對(duì)象晉升失敗，當(dāng)啟用了擔(dān)保分配，每次晉升會(huì)檢查年老代的內(nèi)存是否夠大于年輕代平均晉升對(duì)象的大小，如果小于將會(huì)進(jìn)行FULLGC，日志會(huì)顯示Prommotion faile引起fullGC

2, JDK6后默認(rèn)都開啟了擔(dān)保分配

再解釋下GC的幾個(gè)名詞

有幾個(gè)誤區(qū)：

FULL GC ， Major GC ， Minor GC

Minor GC 就是年輕代清理，這個(gè)好理解

FULL GC 指整個(gè)永久代（或G1的Metaspace代）的和堆內(nèi)存，堆外內(nèi)存一起清理. 在GC日志里的FULL GC指的是這個(gè)

Major GC 年老代的清理，在jstat -gc 里的FGC只是指這個(gè)，只是年老代的GC而已

詳細(xì)：https://plumbr.eu/handbook/garbage-collection-in-java

誤區(qū)：jstat 的FGC，它統(tǒng)計(jì)的僅僅是STW的次數(shù)，即兩個(gè)init-mark和 remark的階段

問題：

引起FULL GC的原因有哪些呢？

1、System.gc()方法的調(diào)用
2、老年代代空間不足
3、永生區(qū)空間不足
4、CMS GC時(shí)出現(xiàn)，如GC日志中找到promotion failed（晉升失敗）和concurrent mode failure（回收時(shí)有對(duì)象要分配）
5、統(tǒng)計(jì)得到的Minor GC晉升到舊生代的平均大小大于老年代的剩余空間
6、空間碎片太多，堆中分配很大的對(duì)象（如果如此，建議每次FULLGC后開啟壓縮）

如何查看GC 發(fā)生的原因呢？

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

1，這種跑批的任務(wù)不應(yīng)該和服務(wù)放一塊后面，應(yīng)該是單獨(dú)的模塊

2. 對(duì)于對(duì)賬，我的解決是后面放mongoDB，然后拿出來進(jìn)行對(duì)賬，完全是個(gè)離線處理的過程了

3，感謝各位的疑問。其實(shí)不一定是對(duì)賬，很多系統(tǒng)會(huì)把跑批和服務(wù)放一塊，如果跑批涉及到把數(shù)據(jù)load到內(nèi)存的話，一定要注意垃圾回收了。不然容易觸發(fā)CMS的GC。而且經(jīng)過我測試，每次到了老年代的50%就會(huì)不斷觸發(fā)GC，如果跑批任務(wù)持續(xù)時(shí)間比較久，不釋放對(duì)象，將不停的Major GC。

有個(gè)疑問

上面例子中，我加上 +XX:CMSInitiatingOccupancyFraction=80 后，還是會(huì)不停的Major GC( 例子中只占50%)，待解答

持續(xù)更新留言問題，解答疑問

歡迎關(guān)注我的公眾號(hào)，專注重現(xiàn)各種線上的BUG

或搜 “包子的實(shí)驗(yàn)室”

總結(jié)

以上是生活随笔為你收集整理的一个大对象引起的血案，GC的踩坑实录的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。

上一篇：【HUST】网安｜计算机网络安全实验｜实
下一篇：使用DVC管理大文件变更历史（基于git

日韩av黄I国产麻豆传媒I国产91av视频在线观看I日韩一区二区三区在线看I美女国产在线I麻豆视频国产在线观看I成人黄色短片

一个大对象引起的血案，GC的踩坑实录

總結(jié)