本文是好友阿飞写的, 并且经过作者同意发的原创!
前言
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 -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 统计信息
根据这张图输出数据, 可以得到如下一些信息:
JVM 运行总时间为 6944534 秒(day 24 3600+hour 3600+minutes 60+second)
YoungGC 频率为 4s / 次(建议通过 GC 日志中两次 YoungGC 时间差计算得出)
CMS GC 频率为 9 天 / 次(FGC=18, 即最多发生 9 次 CMS GC, 所以 CMS GC 频率为 80/99 天 / 次)
每次 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 区增长速度;
异常的大对象. 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
来源: http://www.tuicool.com/articles/6RnMVfI