×

初步诊断你的GC

96
阿飞Javaer
2017.11.27 17:25* 字数 3075

前言

JVM的GC机制让Java程序员省去了自己垃圾回收的烦恼,大大提高了生产效率。但是正因为JVM垃圾回收机制足够优秀,导致很多Java程序员对JVM这个黑盒了解甚少,很多人没有去了解它,很多人也没机会去了解它。然而要想成为一名优秀的Java程序员,了解JVM和它的GC机制,写出JVM GC机制更喜欢的代码,是必须要掌握的一门技术;

这篇文章我主要说一下如何初步诊断JVM的GC是否正常,重点讲解诊断GC,而不是JVM基础和GC基础。所以看这篇文章,需要对JVM有一定的了解,比如常用的垃圾回收器,堆的模型以及分代等,如果你还对JVM一无所知,那么请先花点时间看一下周志明的<<深入理解Java虚拟机>>,重点关注"第二部分 自动内存管理机制"。

GC概念纠正

对GC机制有一定了解的同学都知道,GC主要有YoungGC,OldGC,FullGC(还有G1中独有的Mixed GC,收集整个young区以及部分Old区,提及的概率相对少很多,本篇文章不打算讲解),在讲解如何判断这三种GC是否正常之前,先再次解释一下这三种GC,因为很多很多的同学对OldGC和FullGC有误解;

  • YoungGC:应该是最没有歧义的一种GC了,只是有些地方称之为Minor GC,或者简称YGC,都是没有问题的;
  • OldGC:截止Java发展到现在JDK9为止,只单独回收Old区的只有CMS GC,且是CMS的concurrent collection模式(CMS有两种模式,请参考寒泉子的文章JVM源码分析之SystemGC完全解读)。G1出来之前,CMS GC也是OLTP系统最常用的;而JDK8以前默认的垃圾回收器ParallelOldGC,在Old满后触发的是FullGC;
  • FullGC:有些地方称之为Major GC,Major GC通常是跟FullGC是等价的,都是收集整个GC堆。但因为HotSpot VM发展了这么多年,外界对各种名词的解读已经完全混乱了,当有人说“Major GC”的时候一定要问清楚他想要指的是上面的FullGC还是OldGC(参考R大的Major GC和Full GC的区别)。对这个GC的误解最大,尤其最常用的ParNew+CMS组合,很多人误解FullGC可能是受到jstat结果的影响。如果配置了CMS垃圾回收器,那么jstat中的FGC并不表示就一定发生了FullGC,很有可能是发生了CMS GC而且每发生一次CMS GC,jstat中的FGC就会+2(因为CMS GC时初始化标记和重新标记都会STW,所以FGC的值会+2,可以通过让JVM按照预期GC提供的代码验证);事实上,FullGC的触发条件比较苛刻,判断是否发生了FullGC最好通过GC日志,所以强烈建议生产环境开启GC日志,它的价值远大于它对性能的影响;

FullGC触发条件

  • 没有配置 -XX:+DisableExplicitGC情况下System.gc()可能会触发FullGC;
  • Promotion failed;
  • concurrent mode failure;
  • Metaspace Space使用达到MaxMetaspace阈值;
  • 执行jmap -histo:live或者jmap -dump:live

说明:统计发现之前YGC的平均晋升大小比目前old gen剩余的空间大,触发CMS GC;Metaspace Space使用达到Metaspace阈值是触发CMS GC;

执行jmap -histo:live触发FullGC的gc log如下--关键词Heap Inspection Initiated GC,通过jstat -gccause pid 2s的LGCC列也能看到同样的关键词:
[Full GC (Heap Inspection Initiated GC) 2018-03-29T15:26:51.070+0800: 51.754: [CMS: 82418K->55047K(131072K), 0.3246618 secs] 138712K->55047K(249088K), [Metaspace: 60713K->60713K(1103872K)], 0.3249927 secs] [Times: user=0.32 sys=0.01, real=0.32 secs]

执行jmap -dump:live触发FullGC的gc log如下--关键词Heap Dump Initiated GC,通过jstat -gccause pid 2s的LGCC列也能看到同样的关键词:
[Full GC (Heap Dump Initiated GC) 2018-03-29T15:31:53.825+0800: 354.510: [CMS2018-03-29T15:31:53.825+0800: 354.510: [CMS: 55047K->56358K(131072K), 0.3116120 secs] 84678K->56358K(249088K), [Metaspace: 62153K->62153K(1105920K)], 0.3119138 secs] [Times: user=0.31 sys=0.00, real=0.31 secs]

健康的GC

诊断GC的第一步,当然是知道你的JVM的GC是否正常。那么GC是否正常,首先就要看YoungGC,OldGC和FullGC是否正常;无论是定位YoungGC,OldGC,FullGC哪一种GC,判断其是否正常主要从两个维度:GC频率和STW时间;要得到这两个维度的值,我们需要知道JVM运行了多久,执行如下命令即可:

ps -p pid -o etime

运行结果参考,下面的运行结果表示这个JVM运行了24天16个小时37分35秒,如果JVM运行时间没有超过一天,执行结果是这样"16:37:35"

[afei@ubuntu ~]$ ps -p 11864 -o etime
    ELAPSED
24-16:37:35

那么怎样的GC频率和STW时间才算是正常呢?这里以我以前开发过的一个读多写少的dubbo服务作为参考,该dubbo服务基本情况如下:

  • 日调用量1亿+次,接口平均响应时间6ms以内
  • 4个JVM
  • 每个JVM设置Xmx和Xms为4G,Xmn1G
  • 4核CPU&8G内存服务器
  • JDK7
  • AWS云虚拟机

GC情况如下图所示:


GC统计信息

根据这张图输出数据,可以得到如下一些信息:

  1. JVM运行总时间为6944534秒(day*24*3600+hour*3600+minutes*60+second)
  2. YoungGC频率为4s/次(建议通过GC日志中两次YoungGC时间差计算得出)
  3. CMS GC频率为9天/次(FGC=18,即最多发生9次CMS GC,所以CMS GC频率为80/9≈9天/次)
  4. 每次YoungGC的时间为6ms(通过YGCT/YGC计算得出)
  5. FullGC几乎没有(JVM总计运行80天,FGC才18,即使是18次FullGC,FullGC频率也才4.5天/次,更何况实际上FGC=18肯定包含了若干次CMS GC)

根据上面的GC情况,给个可参考的健康的GC状况

  1. YoungGC频率5秒/次;
  2. CMS GC频率不超过1天/次;
  3. 每次YoungGC的时间不超过20ms;
  4. FullGC频率尽可能完全杜绝;

说明:G1&CMS时,FullGC回收算法会退化成Serial+SerialOld,即单线程串行回收,且完全STW,影响很大且STW时间完全不可预估,所以FullGC频率尽可能完全杜绝。另外,可参考的健康的GC状况这里只是参考,不是绝对,不能说这个GC状况有多好,起码横向对比业务规模,以及服务器规格,你的GC状况不能与上面的dubbo服务有明显的差距;

了解GC健康时候的样子,那么接下来把脉你的JVM GC,一一讲解YoungGC,OldGC,FullGC。看看是有疾在腠理,还是在肌肤,还是在肠胃,甚至已经在骨髓病入膏肓了;

YoungGC

YoungGC是最频繁发生的,发生的概率是OldGC和FullGC的的10倍,100倍,甚至1000倍。同时YoungGC的问题也是最难定位的。这里给出YoungGC定位三板斧(都是踩过坑):

  1. 查看服务器SWAP&IO情况,如果服务器发生SWAP,会严重拖慢GC效率,导致STW时间异常长,拉长接口响应时间,从而影响用户体验(推荐神器sar,yum install sysstat即可,想了解该命令,请搜索"linux sar");
  2. 查看StringTable情况(请参考探索StringTable提升YGC性能
  3. 排查每次YoungGC后幸存对象大小(JVM模型基于分配的对象朝生夕死的假设设计,如果每次YoungGC后幸存对象较大,可能存在问题)
  4. 未完待续……(可以在留言中分享你的IDEA)
排查每次YoungGC后幸存对象大小可通过GC日志中发生YoungGC的日志计算得出:
例如下面两行GC日志,第二次YoungGC相比第一次YoungGC,整个Heap并没有增长(都是647K),说明回收效果非常理想:
2017-11-28T10:22:57.332+0800: [GC (Allocation Failure) 2017-11-28T10:22:57.332+0800: [ParNew: 7974K->0K(9216K), 0.0016636 secs] 7974K->647K(19456K), 0.0016865 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-11-28T10:22:57.334+0800: [GC (Allocation Failure) 2017-11-28T10:22:57.334+0800: [ParNew: 7318K->0K(9216K), 0.0002355 secs] 7965K->647K(19456K), 0.0002742 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
再看下面两行GC日志,第二次YoungGC相比第一次YoungGC,整个Heap从2707K增长到了4743K,说明回收效果一般:
2017-11-28T10:26:41.890+0800: [GC (Allocation Failure) 2017-11-28T10:26:41.890+0800: [ParNew: 7783K->657K(9216K), 0.0013021 secs] 7783K->2707K(19456K), 0.0013416 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2017-11-28T10:26:41.892+0800: [GC (Allocation Failure) 2017-11-28T10:26:41.892+0800: [ParNew: 7982K->0K(9216K), 0.0018354 secs] 10032K->4743K(19456K), 0.0018536 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

可参考的健康的GC状况给出建议YoungGC频率5秒/次,经验值3秒~6秒/次都是比较合理的YoungGC频率;

  • 如果YoungGC频率远高于这个值,例如20秒/次,30秒/次,甚至60秒/次,这种情况下,JVM相当空闲,处于基本上无事可做的状态。建议缩容,减少服务器浪费;
  • 如果YoungGC频率远低于这个值,例如1秒/次,甚至1秒/好多次,这种情况下,JVM相当繁忙,建议follow如下步骤进行初步症断:
  1. 检查Young区,Young区在整个堆占比在25%~40%比较合理,如果Young区太小,建议扩大Xmn。
  2. 检查SurvivorRatio,保持默认值8即可,Eden:S0:S1=8:1:1是一个比较合理的值;

OldGC

上面已经提及:到目前为止HotSpot JVM虚拟机只单独回收Old区的只有CMS GC。触发CMS GC条件比较简单,JVM有一个线程定时扫描Old区,时间间隔可以通过参数-XX:CMSWaitDuration=2000设置(默认就是2s),如果发现Old区占比超过参数-XX:CMSInitiatingOccupancyFraction=75设定值(CMS条件下默认为68%),就会触发CMS GC。建议搭配-XX:+UseCMSInitiatingOccupancyOnly参数使用,简化CMS GC触发条件,只有在Old区占比满足条件的情况下才触发CMS GC;

可参考的健康的GC状况给出建议CMS GC频率不超过1天/次,如果CMS GC频率1天发生数次,甚至上10次,说明你的GC情况病的不轻了,建议follow如下步骤进行初步症断:

  1. 检查Young区与Old区比值,尽量留60%以上的堆空间给Old区;
  2. 通过jstat查看每次YoungGC后晋升到Old区对象占比,如果发现每次YoungGC后Old区涨好几个百分点,甚至上10个点,说明有大对象,建议dump(jmap -dump:format=b,file=app.bin pid)后用MAT分析;
  3. 如果不停的CMS GC,Old区降不下去,建议先执行jmap -histo pid | head -n20 查看TOP20对象分布,如果除了[B和[C,即byte[]和char[],还有其他占比较大的实例,如下图所示中TOP1的Object数组,也可通过dump后用MAT分析问题;
  4. 如果TOP20对象中有StandartSession对象,排查你的业务代码中有没有显示使用HttpSession,例如String id = request.getSession().getId();,一般的OLTP系统几乎不会使用HttpSession,且HttpSession的的生命周期很长,会加快Old区增长速度;
异常的大对象.png

FullGC

  • 如果配置CMS,由于CMS采用标记清理算法,会有内存碎片的问题,推荐配置一个查看内存碎片程度的JVM参数PrintFLSStatistics
  • 如果配置ParallelOldGC,那么每次Old区满后,会触发FullGC,如果FullGC频率过高,也可以通过上面OldGC段落提及的排查方法;
  • 如果没有配置-XX:+DisableExplicitGC,即没有屏蔽System.gc()触发FullGC,那么可以通过排查GC日志中有System字样判断是否System.gc()触发(日志样本:558082.666: [Full GC (System) [PSYoungGen: 368K->0K(42112K)] [PSOldGen: 36485K->32282K(87424K)] 36853K->32282K(129536K) [PSPermGen: 34270K->34252K(196608K)], 0.2997530 secs] );或者通过jstat -gccause pid 2s pid判定,LGCC表示最近一次GC原因,如果为"System.gc",表示由System.gc()触发,GCC表示当前GC原因,如果当前没有GC,那么就是No GC:
 [afei@aliyun~]$ jstat -gccause 23606 2s 5
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC                 
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC               
  0.00 100.00  37.50  83.17  93.31  84.35   5597   24.116     0    0.000   24.116 G1 Evacuation Pause  No GC
System.gc引起的FullGC.png
Java
Web note ad 1