诊断gc是否正常

这篇文章对我的作用很多，在维护大数据集群的时候经常会和java进程打交道，需要分析jvm是否使用合理。

参考链接：https://www.jianshu.com/p/5ace2a0cafa4

 

1、前言

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

 

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

 

2、GC概念纠正

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

1）YoungGC：应该是最没有歧义的一种GC了，只是有些地方称之为Minor GC，或者简称YGC，都是没有问题的；

2）OldGC：截止Java发展到现在JDK9为止，只单独回收Old区的只有CMS GC，且是CMS的concurrent collection模式

（CMS有两种模式，请参考寒泉子的文章JVM源码分析之SystemGC完全解读）。G1出来之前，CMS GC也是OLTP系统最常用的；而JDK8以前默认的垃圾回收器ParallelOldGC，在Old满后触发的是FullGC；

3）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日志，它的价值远大于它对性能的影响；

 

3、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]

 

4、健康的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情况如下图所示：

 

 

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

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。看看是有疾在腠理，还是在肌肤，还是在肠胃，甚至已经在骨髓病入膏肓了；

 

5、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是一个比较合理的值；

 

6、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区增长速度；

 

 

7、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

 

标签：诊断,secs,正常,GC,JVM,YoungGC,gc,CMS,FullGC
来源： https://www.cnblogs.com/gentlemanhai/p/12151904.html