线上某应用的FULLGC分析

最新推荐文章于 2024-09-05 11:51:57 发布

老猿说说

最新推荐文章于 2024-09-05 11:51:57 发布

阅读量303

点赞数

分类专栏： bug

bug 专栏收录该内容

16 篇文章 0 订阅

订阅专栏

过程如下：抽了台线上机器，想看下这段时间机器的gc情况，发现里面有好几个FullGc的日志：

      
      
       
       T23:23:02.009+0800: 21860.015: [Full GC 21860.015: [CMS: 2361237K-&gt;1111804K(4718592K), 4.9917540 secs] 2532961K-&gt;1111804K(5190464K), [CMS Perm : 17397K-&gt;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，当时我想可能的原因有以下几个情况：

cmsgc失败导致（GC日志中没有相关cmsgc失败的日志）
JMAP -histo：现场（人为执行肯定不是）
大对象分配时，空间不够导致（当时还剩下50%内存，并且如果大对象分配，gc日志里面是会有如下WARN的）
内存碎片导致？（由于系统会经常分配一些大数组，这个会加剧碎片化）

第四点是最可能的原因了。于是，接下来怎么验证是否是它导致的呢？加上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原因。