线上某应用的FULLGC分析

简介:
  这2天,排除线上某应用启动内存变化频繁的问题时,额外发现了一个FULLGC的问题,分享给大家。
过程如下:抽了台线上机器,想看下这段时间机器的GC情况,发现里面有好几个FULLGC的日志:
T23:23:02.009+0800: 21860.015: [Full GC 21860.015: [CMS: 2361237K->1111804K(4718592K), 4.9917540 secs] 2532961K->1111804K(5190464K), [CMS Perm : 17397K->17240K(131072K)], 4.9918770 secs] [Times: user=4.96 sys=0.03, real=4.99 secs]

JVM参数设置如下:


-XX:+UseCMSInitiatingOccupancyOnly

-XX:CMSInitiatingOccupancyFraction=60


参数的意思是:在旧区到60%的时候,会触发一次CMSGC,应该出现如下日志:


T20:10:37.803+0800: 3246087.559: [CMS-concurrent-mark-start]

T20:10:38.463+0800: 3246088.220: [CMS-concurrent-mark: 0.661/0.661 secs] [Times: user=3.17 sys=0.56, real=0.66 secs]

T20:10:38.463+0800: 3246088.220: [CMS-concurrent-preclean-start]

T20:10:38.552+0800: 3246088.309: [CMS-concurrent-preclean: 0.069/0.089 secs] [Times: user=0.14 sys=0.04, real=0.09 secs]

T20:10:38.552+0800: 3246088.309: [CMS-concurrent-abortable-preclean-start]


而现在日志里面都是OLD区到2.3G(50%)的时候,就会触发一次FULLGC,而且GC日志里面没有一次正常的CMSGC,现在是什么原因在半路截胡了?
开始怀疑JVM参数是否设置生效,通过JINFO进行查看:

jinfo -flag UseCMSInitiatingOccupancyOnly 20195

jinfo -flag CMSInitiatingOccupancyFraction 20195


一切正常。
出现FULLGC,当时我想可能的原因有以下几个情况:
  1. CMSGC失败导致(GC日志中没有相关CMSGC失败的日志)
  2. JMAP -HISTO:现场 人为执行肯定不是)
  3. 大对象分配时,空间不够导致(当时还剩下50%内存,并且如果大对象分配,GC日志里面是会有如下WARN的)
  4. 内存碎片导致?(由于系统会经常分配一些大数组,这个会加剧碎片化)
第四点是最可能的原因了。于是,接下来怎么验证是否是它导致的呢?加上PRINTGCREASON,先打印出FULLGC的原因,
命令如下:
/JAVA/BIN/JINFO -FLAG +PRINTGCREASON

第二天,查看日志,如下:

GC Cause: Heap Inspection Initiated GC T16:16:01.880+0800: 687439.886: [Full GC 687439.886: [CMS: 2362138K->1180717K(4718592K), 5.6573690 secs] 2700275K->1180717K(5190464K), [C MS Perm : 17531K->17488K(131072K)], 5.6574950 secs] [Times: user=5.59 sys=0.06, real=5.65 secs]

GC原因:堆检查启动GC,FULLGC的原因是这个,看不明白,咨询过后,说这个很可能是因为JAMP -HIST继:活导致的FULLGC。
  那如果是这样,就有可能是有脚本或者定时任务,也可能是什么其他东西,去执行了这个命令,反正据我了解的CS没有做这事。接下来就是找这个“凶手”了,这事情没做过,没啥头绪,看进程也看不出什么,想GREP所有脚本,懒癌又发作了,还是先去群里咨询下有啥简单又省力的办法吧,一下搞定:
[ ~]$ crontab -l */1 * * * * /home/bin/config-monitor.sh >> /home/logs/config-monitor.log 2>&1 [logs]$ cat /home/bin/config-monitor.sh |grep "jmap" jmaplog="/home/jmap.log"; if (count == 3) { / run jmap print "run jmap command : /java/bin/jmap -histo:live "pid" |head -n 20"; system("/java/bin/jmap -histo:live "pid" |head -n 20")>jmaplog; print "#######Server has recovered after running jmap######";


有个定时任务跑一个叫CONFIG-MONITOR.SH的脚本,里面做的事情,基本就是监视内存各个区的比例,超过一定比例,就通过JAMP -HISTO:现场触发下FULLGC,防止溢出===》这个定时任务是CS以前遗留下来的,一直没发现,后续就是评估是否去掉这个定时任务,整个过程告一段落。
总结:
1,问题可能出现的原因,要尽快动手去验证,不要只停留在思考的层面;
2,出现FULLGC的时候,可以通过加上PRINTGCREASON,查看具体GC原因。
相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
相关文章
|
2月前
|
监控 前端开发 Java
案例 2: 某寿险公司核心系统 GC 开销超限问题分析
案例 2: 某寿险公司核心系统 GC 开销超限问题分析
|
3月前
|
存储 SQL Java
jvm性能调优实战 - 27亿级数据量的实时分析引擎,为啥频繁发生Full GC
jvm性能调优实战 - 27亿级数据量的实时分析引擎,为啥频繁发生Full GC
43 0
|
6月前
|
SQL canal 运维
JVM第六讲:线上环境 FGC 频繁,如何解决?
JVM第六讲:线上环境 FGC 频繁,如何解决?
|
监控 Java Linux
大厂的OOM优化和监控方案(二)
大厂的OOM优化和监控方案(二)
大厂的OOM优化和监控方案(二)
|
11月前
|
缓存 监控 算法
因Full GC导致CPU飙升到100%问题排查记录
因Full GC导致CPU飙升到100%问题排查记录
236 0
|
11月前
|
Java
如何优化生产环境的Full GC?
大部分工程师开发完一个系统后,部署生产环境的时候往往不对JVM进行参数设置,直接用默认JVM参数,这绝对是系统负载逐渐增高的时最大问题 如你不设置-Xmx、-Xms之类的堆内存大小,你启动一个系统,可能默认就给你几百MB的堆内存大小,新生代和老年代可能都是几百M。
118 0
|
负载均衡 算法 Java
记一次线上频繁FGC的事件和解决方式
1.大量的请求,调用的地方要注意是否会导致内存的大量消耗,尽可能使用池化技术,单例等,减少创建,销毁的系统开销;2.CMS 的几个缺点,可以参考《深入java虚拟机》,对CPU占用会比较高,无法处理浮动垃圾,还有就是CMS使用的是标记-清除算法,会导致大量的空间碎片,碎片过多的话,导致分配大对象很困难,所以不得不进行FGC,也可能是这个原因导致了本文说的一直FGC的问题。
311 0
记一次线上频繁FGC的事件和解决方式
|
监控 JavaScript Java
大厂的OOM优化和监控方案(一)
大厂的OOM优化和监控方案(一)
大厂的OOM优化和监控方案(一)
|
存储 JSON 监控
大厂的OOM优化和监控方案(三)
大厂的OOM优化和监控方案(三)
大厂的OOM优化和监控方案(三)