初步诊断你的 GC
本文是好友阿飞写的,并且经过作者同意发的原创!
阿飞Javaer,转载请注明原创出处,谢谢!
前言
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;
健康的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 -p11864-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统计信息根据这张图输出数据,可以得到如下一些信息:
JVM运行总时间为6944534秒(day 243600+hour 3600+minutes60+second)
YoungGC频率为4s/次(建议通过GC日志中两次YoungGC时间差计算得出)
CMS GC频率为9天/次(FGC=18,即最多发生9次CMS GC,所以CMS GC频率为80/9≈9天/次)
每次YoungGC的时间为6ms(通过YGCT/YGC计算得出)
FullGC几乎没有(JVM总计运行80天,FGC才18,即使是18次FullGC,FullGC频率也才4.5天/次,更何况实际上FGC=18肯定包含了若干次CMS GC)
根据上面的GC情况,给个 可参考的健康的GC状况
:
-
YoungGC频率5秒/次;
-
CMS GC频率不超过1天/次;
-
每次YoungGC的时间不超过30ms;
-
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定位三板斧(都是踩过坑):
-
查看服务器SWAP&IO情况,如果服务器发生SWAP,会严重拖慢GC效率,导致STW时间异常长,拉长接口响应时间,从而影响用户体验(推荐神器
sar
,yum install sysstat即可,想了解该命令,请搜索"linux sar
"); -
查看StringTable情况(请参考探索StringTable提升YGC性能)
-
排查每次YoungGC后幸存对象大小(JVM模型基于分配的对象朝生夕死的假设设计,如果每次YoungGC后幸存对象较大,可能存在问题)
-
未完待续……(可以在留言中分享你的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如下步骤进行初步症断:
-
检查Young区,Young区在整个堆占比在25%~40%比较合理,如果Young区太小,建议扩大Xmn。
-
检查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如下步骤进行初步症断:
-
检查Young区与Old区比值,尽量留60%以上的堆空间给Old区;
-
通过jstat查看每次YoungGC后晋升到Old区对象占比,如果发现每次YoungGC后Old区涨好几个百分点,甚至上10个点,说明有大对象,建议dump(
jmap -dump:format=b,file=app.bin pid
)后用MAT分析; -
如果不停的CMS GC,Old区降不下去,建议先执行
jmap -histo pid | head -n20
查看TOP20对象分布,如果除了[B和[C
,即byte[]和char[],还有其他占比较大的实例,如下图所示中TOP1的Object数组,也可通过dump后用MAT分析问题; -
如果TOP20对象中有 StandartSession对象,排查你的业务代码中有没有显示使用 HttpSession,例如
String id = request.getSession().getId();
,一般的OLTP系统几乎不会使用 HttpSession,且 HttpSession的的生命周期很长,会加快Old区增长速度;
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 -gccause236062s5
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
0.00100.00 37.50 83.17 93.31 84.35 5597 24.116 0 0.000 24.116G1 Evacuation Pause No GC
0.00100.00 37.50 83.17 93.31 84.35 5597 24.116 0 0.000 24.116G1 Evacuation Pause No GC
0.00100.00 37.50 83.17 93.31 84.35 5597 24.116 0 0.000 24.116G1 Evacuation Pause No GC
0.00100.00 37.50 83.17 93.31 84.35 5597 24.116 0 0.000 24.116G1 Evacuation Pause No GC
0.00100.00 37.50 83.17 93.31 84.35 5597 24.116 0 0.000 24.116G1 Evacuation Pause No GC
System.gc引起的FullGC.png
如果读完觉得有收获的话,欢迎点赞、关注、加公众号【匠心零度】,查阅更多精彩历史!!!