若谷学院
互联网公司技术架构分享

线上某应用的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]_</span>
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-&gt;1180717K(4718592K), 5.6573690 secs] 2700275K-&gt;1180717K(5190464K), [C MS Perm : 17531K-&gt;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 &gt;&gt; /home/logs/config-monitor.log 2&gt;&amp;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")&gt;jmaplog; print "#######Server has recovered after running jmap######";

有个定时任务跑一个叫config-monitor.sh的脚本,里面做的事情,基本就是监视内存各个区的比例,超过一定比例,就通过jamp -histo:现场触发下fullgc,防止溢出===》这个定时任务是cs以前遗留下来的,一直没发现,后续就是评估是否去掉这个定时任务,整个过程告一段落。

总结:

1,问题可能出现的原因,要尽快动手去验证,不要只停留在思考的层面;
2,出现fullgc的时候,可以通过加上PrintGCReason,查看具体GC原因。

原文出自:http://jm.taobao.org/archives/page/11/

好烂呀没啥价值凑合看看还不错很精彩 (还没有人评分)
Loading...
本站文章来自互联网一线技术博客,若有侵权,请联系我们:若谷技术学院 » 线上某应用的FULLGC分析
关注若谷技术,获得个性化即时架构文章推送

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址

全球互联网技术架构,前沿架构参考

联系我们博客/网站内容提交