文档章节

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

爱吃大肉包
 爱吃大肉包
发布于 2017/01/13 18:27
字数 2481
阅读 5.7K
收藏 173

背景:

 

问题:

有个渠道支付服务,负责与所有支付相关服务进行交互,包括 渠道下单支付,渠道成功通知,渠道的对账等

服务4台机,平时跑的都很稳定,通过thrift进行对外提供服务,且平时并未发现访问超时的情况,已经平稳在线上跑了1年多了,没出现过超时问题。

但最近发现,每天到了晚上凌晨2点开始大量服务访问超时,且定位到每次都是抢到对账任务的那台服务出现问题。

 

解决:

后通过监控和打印GC日志发现,出现问题机器服务的Major GC频率增加,应该是内存问题。

故把对账程序拆出后单独部署后, 再没出现服务访问超时情况。

 

分析,对账时,因为要捞出当天支付数据到内存进行对账(随着业务发展订单开始猛增)故触发了GC。其实增加分批limit当然也可以解决。当然像这种对账,订单多了后最好应该是单独分拆模块,进行离线处理了。

这是最近第二次踩到GC的坑了, 第一次是每次访问给每个线程分配的内存过多,并发上来后性能严重降低,导致WEB超时,有必要总结下了

 

 

 

重现下:

 

死磕重现下,

 

模拟业务部分,假使每个业务需要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的原因有哪些呢?

1、System.gc()方法的调用 
2、老年代代空间不足 
3、永生区空间不足 
4、CMS GC时出现,如GC日志中找到promotion failed(晋升失败)和concurrent mode failure(回收时有对象要分配) 
5、统计得到的Minor GC晋升到旧生代的平均大小大于老年代的剩余空间 
6、空间碎片太多,堆中分配很大的对象(如果如此,建议每次FULLGC后开启压缩)

 

如何查看GC 发生的原因呢?

目前能想到的,最简单是 jstat -gccause

 

感谢各位网友的疑问,说明下:

这里对账其实算历史原因,以前系统量不大时是放在了支付模块其实是没问题,后面进行了分拆,

 

1,这种跑批的任务不应该和服务放一块后面,应该是单独的模块

2. 对于对账,我的解决是后面放mongoDB,然后拿出来进行对账,完全是个离线处理的过程了

3,感谢各位的疑问。其实不一定是对账,很多系统会把跑批和服务放一块,如果跑批涉及到把数据load到内存的话,一定要注意垃圾回收了。不然容易触发CMS的GC。 而且经过我测试,每次到了老年代的50%就会不断触发GC,如果跑批任务持续时间比较久,不释放对象,将不停的Major GC。

 

有个疑问

上面例子中, 我加上 +XX:CMSInitiatingOccupancyFraction=80 后,还是会不停的Major GC( 例子中只占50%),待解答

 

持续更新留言问题,解答疑问

欢迎关注我的公众号,专注重现各种线上的BUG

 或搜 “包子的实验室”

 

© 著作权归作者所有

爱吃大肉包

爱吃大肉包

粉丝 64
博文 42
码字总数 38406
作品 0
广州
程序员
私信 提问
加载中

评论(15)

刘万祥
刘万祥
又温故了一下GC的内容.感谢分享😀
若水191
若水191
mark
OSC_yyiVAA
OSC_yyiVAA

引用来自“乌龟壳”的评论

引用来自“爱吃大肉包”的评论

引用来自“乌龟壳”的评论

引用来自“爱吃大肉包”的评论

引用来自“乌龟壳”的评论

gc的事情是很无奈,但是把大量数据读入内存而不是数据库里进行分析这个相当费解啊
日对是批量操作,是先拿出一批和渠道所有对。一条条的话速度跟不上,这里问题主要是一批拿的数据太大了

把要对的数据怼到库里临时表就能一次性对了
是的,感谢提出疑问,如果系统小的时候,把数据放到内存再对其实没任何问题。现在大了这个应该是个离线过程,后面重构已经把要对账的数据丢到了mongoDB。 其实这对账只是个举例,很多系统会把跑批和服务放一块,如果跑批涉及到把数据load到内存的话,一定要注意垃圾回收了。不然容易触发CMS的GC。 而且经过我测试,每次到了老年代的50%就会不断触发GC,如果跑批任务持续时间比较久,不释放对象,将不停的Major GC。

如果是我遇到这个问题,首先第一是想到利用数据库做计算,数据库的优势就是强大的大数据量分析,它会充分利用内存和磁盘,在其中找到最好的平衡,计算超出内存很多倍的数据都没问题。

如果必须load到内存,则考虑加内存而不是优先研究gc。大对象这种东西gc难为无米之炊

是的,不过最后解决也是分拆了系统线下处理了。这里更多想说明的是这种大对象的现象吧。比如读取个大文件,推送批数据等。
py庄稼汉
py庄稼汉
不错,不错,我做对账都是一条一条取,再update
乌龟壳
乌龟壳

引用来自“爱吃大肉包”的评论

引用来自“乌龟壳”的评论

引用来自“爱吃大肉包”的评论

引用来自“乌龟壳”的评论

gc的事情是很无奈,但是把大量数据读入内存而不是数据库里进行分析这个相当费解啊
日对是批量操作,是先拿出一批和渠道所有对。一条条的话速度跟不上,这里问题主要是一批拿的数据太大了

把要对的数据怼到库里临时表就能一次性对了
是的,感谢提出疑问,如果系统小的时候,把数据放到内存再对其实没任何问题。现在大了这个应该是个离线过程,后面重构已经把要对账的数据丢到了mongoDB。 其实这对账只是个举例,很多系统会把跑批和服务放一块,如果跑批涉及到把数据load到内存的话,一定要注意垃圾回收了。不然容易触发CMS的GC。 而且经过我测试,每次到了老年代的50%就会不断触发GC,如果跑批任务持续时间比较久,不释放对象,将不停的Major GC。

如果是我遇到这个问题,首先第一是想到利用数据库做计算,数据库的优势就是强大的大数据量分析,它会充分利用内存和磁盘,在其中找到最好的平衡,计算超出内存很多倍的数据都没问题。

如果必须load到内存,则考虑加内存而不是优先研究gc。大对象这种东西gc难为无米之炊
NickWilde
NickWilde
爱吃大肉包
爱吃大肉包 博主

引用来自“乌龟壳”的评论

引用来自“爱吃大肉包”的评论

引用来自“乌龟壳”的评论

gc的事情是很无奈,但是把大量数据读入内存而不是数据库里进行分析这个相当费解啊
日对是批量操作,是先拿出一批和渠道所有对。一条条的话速度跟不上,这里问题主要是一批拿的数据太大了

把要对的数据怼到库里临时表就能一次性对了
是的,感谢提出疑问,如果系统小的时候,把数据放到内存再对其实没任何问题。现在大了这个应该是个离线过程,后面重构已经把要对账的数据丢到了mongoDB。 其实这对账只是个举例,很多系统会把跑批和服务放一块,如果跑批涉及到把数据load到内存的话,一定要注意垃圾回收了。不然容易触发CMS的GC。 而且经过我测试,每次到了老年代的50%就会不断触发GC,如果跑批任务持续时间比较久,不释放对象,将不停的Major GC。
爱吃大肉包
爱吃大肉包 博主

引用来自“lxbzmy”的评论

对账和支付不应该是一个模块才对。
历史代码,系统上其实现在已经拆开了。 直接查询出来后丢然后用mongoDB对了。 这里举例只是想说下一个大对象。可以看成其他任何操作。 跑批的操作和服务不应该放一块
爱吃大肉包
爱吃大肉包 博主

引用来自“lxbzmy”的评论

对账和支付不应该是一个模块才对。
是的,后面拆了出来。这里其实更想说的是批量操作的一个大对象问题
lxbzmy
lxbzmy
对账和支付不应该是一个模块才对。
卧槽,我的JVM崩了居然是因为……

本人作为JVM调优与DEBUG小能手,在这几年下来也积攒了不少心得体会,现在总结一波。 这些JVM问题,要么是我遇到的,要么是别人遇到了请教我的,大体上都给我留下了比较深刻的印象。解决这些问...

flycash
2019/03/21
0
0
ThreadLocal实现原理详解

ThreadLocal实现原理详解 简书 涤生。 转载请注明原创出处,谢谢! 如果读完觉得有收获的话,欢迎点赞加关注。 介绍 ThreadLocal大家应该不陌生,经常在一些同步优化中会使用到它。它为线程内...

涤生_YinQi
2017/12/03
0
0
JVM--JVM finalize实现原理与由此引发的血案

原创内容,转载请注明出处 本文由一桩因为使用了JAVA finalize()而引发的血案入手,讲解了JVM中finalize()的实现原理和它的陷阱所在,希望能够对广大JAVA开发者起到一点警示作用。除此之外,...

andy521zhu
2015/03/21
444
0
【2016-06-13】一次BufferReader没有close引发的血案

Hive-Web是我司Web端查询Hive数据的服务,功能上比较简单,用户在Web上写一个SQL,Hive-Web将SQL提交到后端的服务执行查询,得到结果的hdfs路径,然后通过hadoop的fs读取文件,将其返回给用户...

rathan0
2016/06/13
585
0
那些年,我们一起踩过的坑(前端防翻车指南)

javascript做为一门脚本语言,由于缺乏约束,以及各种自动容错机制和隐式转换,产生了很多容易误解和容易引发问题的地方, 《javascript语言精髓》一书中,有很大一部分篇幅介绍了javascrip...

windyfancy
2019/06/03
0
0

没有更多内容

加载失败,请刷新页面

加载更多

如何优雅地检测JavaScript中的空闲时间?

是否可以在JavaScript中检测“ 空闲 ”时间? 我的主要用例可能是预取或预加载内容。 空闲时间: 用户不活动或没有使用CPU的时间 #1楼 如果不使用jQuery,则仅使用普通JavaScript: var inac...

技术盛宴
41分钟前
31
0
获取枚举值的属性

我想知道是否可以获取枚举值而不是枚举本身的属性? 例如,假设我有以下枚举: using System.ComponentModel; // for DescriptionAttributeenum FunkyAttributesEnum{ [Description(...

javail
今天
78
0
concurrently 启动多个serve时命令行输出混乱

在script中配置中加入参数 -r "start": "npx concurrently -r \"npm:serve\" \"npm:web\"" 输出比较整洁 输出混乱, 会将有用的信息冲掉...

阿豪boy
今天
48
0
每天AC系列(三):电话号码的字母组合

1 题目 Leetcode第17题。 数字2-9映射字母,给出一个包含字符串的数字,列出字母的所有组合。 2 递归 拿到这样的题目想到了递归实现,创建一个Map映射对应的字母,然后把它传给递归函数,同时...

Blueeeeeee
今天
44
0
Kettle自定义jar包供javascript使用

我们都知道 Kettle 是用 Java 语言开发,并且可以在 JavaScript 里面直接调用 java 类方法。所以有些时候,我们可以自定义一些方法,来供 JavaScript 使用。 本篇文章有参考自:https://www...

CREATE_17
昨天
114
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部