初步诊断你的 GC

标签: dev | 发表时间:2018-03-29 00:00 | 作者:
出处:http://itindex.net/relian

本文是好友阿飞写的,并且经过作者同意发的原创!
阿飞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统计信息

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

  1. JVM运行总时间为6944534秒(day 243600+hour 3600+minutes60+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的时间不超过30ms;

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



如果读完觉得有收获的话,欢迎点赞、关注、加公众号【匠心零度】,查阅更多精彩历史!!!


相关 [诊断 gc] 推荐:

初步诊断你的 GC

- - IT瘾-dev
本文是好友阿飞写的,并且经过作者同意发的原创. 阿飞Javaer,转载请注明原创出处,谢谢. JVM的GC机制让Java程序员省去了自己垃圾回收的烦恼,大大提高了生产效率. 但是正因为JVM垃圾回收机制足够优秀,导致很多Java程序员对JVM这个黑盒了解甚少,很多人没有去了解它,很多人也没机会去了解它.

Java GC 调优

- - Darktea
关于 Java GC 已经有很多好的文档了, 比如这些:. 但是这里还是想再重点整理一下 Java GC 日志的格式, 可以作为实战时的备忘录.. 同时也会再整理一下各种概念. 一, JDK 6 提供的各种垃圾收集器. 先整理一下各种垃圾收集器.. 新生代收集器: Serial, ParNew, Parallel Scavenge (MaxGCPauseMillis vs.

[译]GC专家系列3-GC调优

- - SegmentFault 最新的文章
原文链接: http://www.cubrid.org/blog/dev-platform/how-to-tune-java-garbage-collection/. 本篇是”GC专家系列“的第三篇. 在第一篇 理解Java垃圾回收中我们学习了几种不同的GC算法的处理过程,GC的工作方式,新生代与老年代的区别.

GC 日志分析

- - 码蜂笔记
不同的JVM及其选项会输出不同的日志. 生成下面日志使用的选项: -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:d:/GClogs/tomcat6-gc.log. 最前面的数字 4.231 和 4.445 代表虚拟机启动以来的秒数.

初级分代GC

- - C++博客-首页原创精华区
通常情况下GC分为两种,分别是:扫描GC(Tracing GC)和引用计数GC(Reference counting GC). 其中扫描GC是比较常用的GC实现方法,其原理是:把正在使用的对象找出来,然后把未被使用的对象释放. 而引用计数GC则是对每个对象都添加一个计数器,引用增加一个计数器就加一,引用减少一个计数器就减一,当计数器减至零时,把对象回收释放.

一个GC频繁的Case

- loudly - BlueDavy之技术Blog
前两天碰到一个很诡异的GC频繁的现象,走了不少弯路,N种方法查找后才终于查明原因了,在这篇blog中记录下,以便以后碰到这类问题时能更快的解决. 前两天一位同学找到我,说有个应用在启动后就一直Full GC,拿到GC log先看了下,确实是非常的诡异,截取的部分log如下:. 这个日志中诡异的地方在于每次Full GC的时候旧生代都还有很多的空间,于是去看来下启动参数,此时的启动参数如下:.

Java GC日志查看

- - Java - 编程语言 - ITeye博客
Java中的GC有哪几种类型. 虚拟机运行在Client模式的默认值,打开此开关参数后,. 使用Serial+Serial Old收集器组合进行垃圾收集. 打开此开关参数后,使用ParNew+Serial Old收集器组合进行垃圾收集. 打开此开关参数后,使用ParNew+CMS+Serial Old收集器组合进行垃圾收集.

GC的基本算法

- - 非技术 - ITeye博客
1、引用计数(reference counting).     原理:此对象有一个引用,则+1;删除一个引用,则-1. 缺点:无法处理循环引用的问题. 对象A和B分别有字段b、a,令A.b=B和B.a=A,除此之外这2个对象再无任何引用,那实际上这2个对象已经不可能再被访问,但是引用计数算法却无法回收他们.

CMS gc实践总结

- - 编程语言 - ITeye博客
声明:原文转自http://www.blogjava.net/killme2008/archive/2009/09/22/295931.html,该文所有合法权益归原作者所有,仅在此做技术分享使用. 首先感谢阿宝同学的帮助,我才对这个gc算法的调整有了一定的认识,而不是停留在过去仅仅了解的阶段. 在读过sun的文档和跟阿宝讨论之后,做个小小的总结.

面向GC的Java编程

- - 并发编程网 - ifeve.com
Java程序员在编码过程中通常不需要考虑内存问题,JVM经过高度优化的GC机制大部分情况下都能够很好地处理堆(Heap)的清理问题. 以至于许多Java程序员认为,我只需要关心何时创建对象,而回收对象,就交给GC来做吧. 甚至有人说,如果在编程过程中频繁考虑内存问题,是一种退化,这些事情应该交给编译器,交给虚拟机来解决.