起初没有人在意这场 GC,直到它影响到了每一天!
前言
本文记录了一次排查 FullGC 导致的 TP99 过高过程,介绍了一些排查时思路,线索以及工具的使用,希望能够帮助一些新手在排查问题没有很好的思路时,提供一些思路,让小白也能轻松解决 FullGC 问题,文中实际提到的参数配置不一定适合其他业务场景,在调优自己的项目时还是需要实际试验过才能得出最佳参数配置
我也是小白,如有不合理的地方,欢迎大佬们进行指正
因为线上服务器,我们大部分是没有 SSH 权限的,没有办法直接执行命令获取容器信息,所以排查过程中只能借助平台提供的工具,平台提供的工具还是挺全的,本文主要用到的工具有: JDOS 容器智能监控,JDOS 进程查询,SGM 容器监控信息,SGM 方法调用查询
以下几个工具简单介绍:
http://sgm-server.jd.com/
http://jagile.jd.com/jdosCD/jdt/apps
JDOS容器智能监控: 查看容器的CPU,内存,磁盘,IO等信息
JDOS进程查询: 查看Java进程编号,执行常用的Java内存进程查看命令
SGM容器监控信息: 查看JVM虚拟机内存变更历史记录
SGM方法调用查询: 查看某一次关键接口调用的上下依赖,时间分布
起因 - 偶尔出现接口超时
一开始偶尔会收到报警邮件,显示有些接口调用时间比较长,抽查了一些接口,发现大部分都是调用下游 JSF 时间比较长,导致响应比较慢,这时候就没太在意,接下来继续观察了几天,发现一个规律,大部分邮件都是每天 10 点
排查定位问题
首先确认了 10 点这个时间点有没有定时任务之类的操作,经过询问确定这个时间点是仓库出库高峰期,导致业务量出现峰值 (调用量变大可能是激发 FullGC 问题,成为问题暴漏的导火线)
第二部就是确认是数据库原因,还是业务代码,还是 JSF 下游接口达到极限原因,到这一步还是未知的,在这用到了 SGM 的接口调用查询工具,下图中我们看到,这次调用 JSF 也是挺高的 (这个没有太好办法,除非让下游优化,所以暂时忽略),但是还有一个是 logic,这个就是逻辑处理,如果没有那个 FullGC 提示,就需要去分析代码的处理是否有问题,这通过那行红色字体的提示,很显然我们确定了是 FullGC 导致的问题
我们去查看一下容器的 FullGC 情况,确实发现这个时间点的 FullGC 特别频繁,到此已经把问题范围定位到就是 FullGC 导致的
FullGC 问题排查
Full GC 触发条件：
到这里我们需要确定一个问题 : “触发 FullGC 的条件是什么？”，新手可以去博客搜索，当然最好是能记住这个知识点。注意这不是确定 “什么原因导致的 FullGC？”，因为这个问题原因太多了，我们要一步一步排查。 下面是我查到的资料，粘到这里供参考.
Minor GC 触发条件：当 Eden 区满时，触发 Minor GC。
Full GC 触发条件：
- （1）调用 System.gc() 时，系统建议执行 Full GC，但是不必然执
- （2）老年代空间不足
- （3）方法区空间不足
- （4）通过 Minor GC 后进入老年代的平均大小大于老年代的可用内存
- （5）由 Eden 区、From Space 区向 To Space 区复制时，对象大小大于 To Space 可用内存，则把该对象转存到老年代
这里在代码中并没有找到 System.gc() 的显示调用,一般我们也不会调用这个方法,所以我们直接看第二种情况,到 SGM 中查看老年代变化,结果发现老年代频繁达到 90%,而这个时间正好可以跟上面 GC 时间对上.
对象进入老年代的几种情况
我们都知道,老年代的对象应该是存活时间很长的对象,但是我们发现这些对象都在 FullGC 时被释放掉了,他们为什么到了老年代呢? 这时候我们需要确定的第二个问题是:“什么情况下对象会进入老年代？” 查资料后有以下几种情况
年龄够了: 躲过 15 次 (默认配置是 15 次) minorGC 之后从新生代进入老年代；
大对象: 大对象直接进入老年代。有一个 JVM 参数 '-XX:PretenureSizeThreshold' 设置值为字节数，创建超过该大小的对象直接进入老年代,如果没有配置这个参数,这个值好像默认是 1M。
动态年龄判断：当前放对象的 Survivor 区，相同年龄的一批对象（以及小于该年龄）的总内存大于该区的内存的 50%，大于该年龄的其他老对象，就会进入老年代（例如 1,2,3 岁年龄的对象占了 S 区的 50% 以上，就会把大于 3 岁的对象移动到老年代去。所以尽量让 S 区中的对象，占比尽量少于 50%）；
剩的总量太多: Eden 区存活对象太多，超过了 Survivor 的大小，就直接把这些对象都转移到老年代去。（JDK1.8 空间担保机制）
首先分析第一种情况,如果出现大批量这样的对象,代码中出现了长时间引用 (例如:静态 Map 只加不删),但是我们可以看到,这些对象在每次 FullGC 都被释放掉了,说明这批对象存活的时间并不长, 而且代码排查也没发现这种代码,暂时排除这种情况 (这的代码因为是工具包的代码,所以没有太深纠,这为续集留个伏笔). 第二种情况,大对象,我们到 JDOS 下载下来 JMap-dump 内存快照和 JMap-Histo 对象统计信息,经过对 FullGC 钱 dump 分析,结合 GC 前 GC 后对象统计结果,并没有发现大量的大对象,这个基本也排除
通过 JMAT(Eclipse Memory Analysis Tools) 导入 dump 文件进行分析，内存泄漏问题一般我们直接选 Leak Suspects 即可，mat 给出了内存泄漏的建议。另外也可以选择 Top Consumers 来查看最大对象报告。和线程相关的问题可以选择 thread overview 进行分析。除此之外就是选择 Histogram 类概览来自己慢慢分析，大家可以搜搜 mat 的相关教程。
接下来就是第三种和第四种情况,这时候我们需要取查看年轻代三块区域的变化,尤其是 Survivor 区域,下图是当时一个情况,S 区大小一直在变化,而且基本一致保持在 50% 以上,这时候想到了一个 JVM 高版本特性,会自动打开 UseAdaptiveSizePolicy(动态调整),查资料后发现,好多人反应这个参数会导致对象跨过 S 区,直接跑到老年代的情况,我们看到在调用量持续很高的情况,尽然调整到了 17M,这肯定会导致容纳不下当时存活的对象
UseAdaptiveSizePolicy 开关参数-XX:+UseAdaptiveSizePolicy 是一个开关参数，当这个参数打开之后，虚拟机会根据当前系统的运行情况收集性能监控信息，动态调整这些参数以提供最合适的停顿时间或最大的吞吐量，这种调节方式称为 GC 自适应的调节策略（GC Ergonomics）。
定位到 UseAdaptiveSizePolicy 问题
既然这有问题,我们尝试关闭一下这个参数看下效果,下面是老年代,S 区和 FullGC,在关闭前和关闭后的效果,关闭之后 S 区大多数时间有充足的空间,而且,老年代和 FullGC 图也安稳了很多 关闭 AdaptiveSizePolicy 的方式
开启：-XX:+UseAdaptiveSizePolicy(JDK1.8 Parallel Scavenge收集器默认)
关闭：-XX:-UseAdaptiveSizePolicy
发现新的问题
上图中虽然已经安稳了很多,但是还是有一点小问题,频繁 FullGC 虽然没有了,但是一个小时还是会出现一次 FullGC,而且这时候老年代还没有满,这种频率的 FullGC,理论上也是不允许的. 我们回到第一个问题,FullGC 触发条件,第三个,我们赶紧看了下永久代,也就是元空间,如下图,这一看不得了,元空间也在频繁变动,而且达到 300M 左右时会触发一次 FullGC 释放掉.
tips: 这里是没有配置元空间的大小的,也没有配置元空间的理论上元空间无限大,不会满,查询资料后解释是,元空间也会根据当前已使用进行动态调整,当达到上次调整值 90% 后就会 FullGC,所以每次 FullGC 元空间大小在 200M 到 500M 不等
元空间内存排查
这时猜测可能是代码中出现了大量的动态类的声明,想要定位哪些类需要 jvm 启动参数加上打印类加载和卸载的参数,顺带把 GC 日志开关也打开
-XX:+TraceClassUnloading -XX:+TraceClassLoading -XX:+PrintGCDetails
打开后查看日志发现一个频繁加载和卸载的类 [com.googlecode.aviator.Expression], 经查询资料,这个是 aviator 工具的一个规则引擎类,在加载规则时会动态加载一个类,默认不使用缓存,可以打开缓存防止频繁声明新类
修改代码后重新部署,一小时一次的 FullGC 也没了,如下图
总结
发现的问题: 问题一: AdaptiveSizePolicy 导致对象提前进入老年代,老年代增长速度快,导致频繁 FullGC 解决方式: 关闭：-XX:-UseAdaptiveSizePolicy
问题二: 元空间不断增长,导致一小时一次 FullGC 解决方式: 修改逻辑代码防止频繁加载新类
在排查问题时尽可能先找直接原因,缩小排查跨度,不要一步就想知道根本原因,每个线索都要问个为什么,不正常的现象肯定是有原因的.
下面是 FullGC 排查思路参考脑图
作者：京东保险 陈林辉
来源：京东云开发者社区 转载请注明来源