专栏名称: OSC开源社区
OSChina 开源中国 官方微信账号
目录
相关文章推荐
程序员的那些事  ·  B站员工代码投毒“封杀”用户账号,并放话:“ ... ·  3 天前  
程序员的那些事  ·  突发!Tiktok 没“凉”到 12 ... ·  4 天前  
51好读  ›  专栏  ›  OSC开源社区

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

OSC开源社区  · 公众号  · 程序员  · 2017-01-18 08:26

正文


踩过很多次GC的坑,基本每次性能问题,除了数据库,其它高发地区就是GC问题了


问题:

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


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


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

解决


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


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


分析


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



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


重现下


死磕重现下,


模拟业务部分,假使每个业务需要500ms返回,代码如下:



放入tomcat,加入垃圾回收方式和堆内存大小,打印垃圾回收日志




用jmeter压测1分钟后,发现正常,每次返回均在500毫秒左右,日志里也没有出现访问超时。



加入模拟对账部分代码,1分钟后对账开启,持续提供服务,为了让它触发GC,模拟加载了1G的待对账数据,(当然,在生产环境里只是一个大对象,但OU区本来就有东西了)


和上面一样的参数启动 tomcat, 1G内存,CMS回收,用jmeter压测1分钟后,发现 Major GC大量发生,截取一周期的Major GC日志如下:



此时的用jstat查看的话情况如下:


导致结果,大量接口访问超时,截取一部分日志如下:



上面是HTTP的,thrift访问其实也是一样的。



总结


1, 内存不够用,JVM用到SWAP

如果每次GC时间不合理时,如: FGC=10,FGCT=1, 基本可以肯定是用到了SWAP内存区了 (当然也和你内存大小有关, 指一般系统内存在8G附近)



2, 用到大对象,导致频繁FGC( FULLGC

和 Major GC 对性能都有严重影响)

看很多资料上说是60%触发Major GC, 但经测试发现, 在OU到了50%时开始不断触发Major GC


3,YGC变动越来越久, 如用到了string.intern()方法. (比如在 fastjson 中有用到), 

原因: string.intern() 往常量池加如数据。 而ROOT GC时, 需要扫描所有常量作为根节点, 当常量池越大量增加时,扫描的数据时间增加


4,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%),待解答





推荐阅读

2016 年度开源中国新增开源软件排行榜 TOP 100

2016 年度最受欢迎中国开源软件 TOP 20

2016 年度码云热门项目排行榜 TOP 50

2017 值得关注的十个开源项目

2017 最值得关注的十大 APP、Web 界面设计趋势

点击“阅读原文”查看更多精彩内容