GC问题诊断

前言

最近上了个双11的项目，因为时间紧任务中，因此楼主也中间被拉进组里进行支持，项目分为了三期，第一期项目以前虽然写完了可是只是功能堆砌的上线了没有流量因此系统有什么问题反映不出来，彻底没有技术评审和性能压测，因此好很差用只能到放到双11当天才知道，我以为这个太冒险了。

我参与了二期的部分功能开发，一介入就有种“墨菲定律”的感受，总感受这个项目有“毒”。

由于明显的感受到你们都在忙需求，甚至深陷需求中，而对于整个需求最熟悉的（由于原有老系统大部分人离职了，就剩下一个职级不高的同窗了）对于整个技术方案的把控能力也是不足的，形成整个设计方案存在比较大的问题，好比方案设计复杂：

• 引入的业务术语不统一，好比有的叫活动，有的的营销券，形成大部分新介入的同窗在业务理解上存在比较大的压力。
• 表设计不够统一，好比有的表中完成状态是1，有的完成状态变为了2了，1成了别的状态。
• 表的设计过于琐碎和复杂，变成了case by case的，每一个小功能都对应一个表，若是在一个相对聚合的功能表现上则须要维护N张表了。
• 代码层次设计上没有必定的抽象能力，好比公司有SOA平台，理论上功能会有必定的归档到对应的服务里面去，可是此次设计却将一些非领域相关功能的东西又设计回来了，简单点说就是将原本好好的微服务又设计成了大一体服务。
• 等。

这只是列的几个在开发过程当中RD同窗反映和后续QA同窗（QA同窗在测试过程当中都会提出更好的设计方案）反映的几个明显的问题，若是光在技术角度看有更多的问题。

固然这还只是简单的业务功能角度看设计有问题，考虑到技术角度，原本项目总体是为双11服务的，理论上是一个大的流量高峰，可是在整个设计和评审过程当中根本没有人去讨论性能，容量评估等问题，这样确定是有必定的隐藏问题。

因而我第一时间向这个项目的技术负责人反映了相似的问题，说须要将这些问题在从新捋一下，可是项目技术负责人说，时间已经比较紧了，这期先这样吧，问题在慢慢说，个人想法是“磨刀不误砍柴工”，技术负责人的想法是“车到山前必有路”。

因而双11这个项目就先上线了，上线第一天在双11以前进行了必定的演练，而后就是各类FullGC了。

诊断须要对JVM有必定的了解，好比经常使用的垃圾回收器，Java堆模型。主要说下FullGC。

FullGC

Major GC一般和FullGC是等价的，都是收集整个GC堆。

FullGC触发缘由：

没有配置 -XX:+DisableExplicitGC状况下System.gc()可能会触发FullGC；

Promotion failed；

concurrent mode failure；

Metaspace Space使用达到MaxMetaspaceSize阈值；

执行jmap -histo:live或者jmap -dump:live；

判断GC是否正常

主要依靠两个维度：GC频率和STW时间。

命令有：ps -p pid -o etime

[afei@ubuntu ~]$ ps -p 11864 -o etime
    ELAPSED
24-16:37:35
结果表示这个JVM运行了24天16个小时37分35秒，若是JVM运行时间没有超过一天，执行结果相似这样"16:37:35"。

什么样的GC频率和STW时间才算正常呢？ 举个例子：JVM设置Xmx和Xms为4G而且Xmn1G。 获得的信息：

JVM运行总时间为7293378秒（80*24*3600+9*3600+56*60+18）

YoungGC频率为2秒/次（7293378/3397184，jstat结果中YGC列的值）

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状况：

YoungGC频率不超过2秒/次；

CMS GC频率不超过1天/次；

每次YoungGC的时间不超过15ms；

FullGC频率尽量彻底杜绝；

YGC

YGC是最频繁发生的，发生的几率是OldGC和FullGC的的10倍，100倍，甚至1000倍。同时YoungGC的问题也是最难定位的。这里给出YGC定位三板斧（都是踩过坑）：

查看服务器SWAP&IO状况，若是服务器发生SWAP，会严重拖慢GC效率，致使STW时间异常长，拉长接口响应时间，从而影响用户体验（推荐神器sar，yum install sysstat便可，想了解该命令，请搜索"linux sar"）；

查看StringTable状况（请参考：探索StringTable提高YGC性能）

排查每次YGC后幸存对象大小（JVM模型基于分配的对象朝生夕死的假设设计，若是每次YGC后幸存对象较大，可能存在问题）

排查每次YGC后幸存对象大小可经过GC日志中发生YGC的日志计算得出，例以下面两行GC日志，第二次YGC相比第一次YGC，整个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日志，第二次YGC相比第一次YGC，整个Heap从2707K增加到了4743K，说明回收效果不太理想，若是每次YGC时发现好几十M甚至上百M的对象幸存，那么可能须要着手排查了：

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情况给出建议YGC频率不超过2秒/次，经验值2秒~10秒/次都是比较合理的YGC频率；

若是YGC频率远高于这个值，例如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设置（默认就是2s），扫描发现Old区占比超过参数-XX:CMSInitiatingOccupancyFraction设定值（CMS条件下默认为68%），就会触发CMS GC。 建议搭配-XX:+UseCMSInitiatingOccupancyOnly参数使用，简化CMS GC触发条件，只有在Old区占比知足-XX:CMSInitiatingOccupancyFraction条件的状况下才触发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 -n10 查看TOP10对象分布，若是除了[B和[C，即byte[]和char[]，还有其余占比较大的实例，以下图所示中排名第一的Object数组，也可经过dump后用MAT分析问题；

若是TOP10对象中有StandartSession对象，排查你的业务代码中有没有显示使用HttpSession，例如String id = request.getSession().getId();，通常的OLTP系统都是无状态的，几乎不会使用HttpSession，且HttpSession的的生命周期很长，会加快Old区增加速度；
好比系统中是TOP对象中有StandartSession对象，而且占比较大，后面让他排查发如今接口中使用了HttpSession生成一个惟一ID，让他改为用UUID就解决了OldGC频繁的问题。

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：

System.gc引发的FullGC