关于java:记一次FullGC的排查经历从FullGC日志到业务代码

问题的产生

简略介绍下咱们服务的背景，咱们的服务是一个应用相似 dubbo 的 RPC 框架以及若干 Spring 全家桶组合起来的微服务架构，大抵构造能够参考下图。
Java 服务应用的是 CMS 的垃圾回收器。

某天忽然收到一台实例（即一个 Java 利用）产生 FullGC 日志的报警，如上图红色标记的服务，FullGC 的日志信息如下：

2020-07-25T14:55:07.481+0800: 155286.031: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13965759K(13965760K)] 16377019K(16496128K), 0.1756459 secs] [Times: user=2.53 sys=0.00, real=0.18 secs]
2020-07-25T14:55:07.657+0800: 155286.207: [CMS-concurrent-mark-start]
2020-07-25T14:55:08.507+0800: 155287.057: [Full GC (Allocation Failure) 2020-07-25T14:55:08.507+0800: 155287.057: [CMS2020-07-25T14:55:11.932+0800: 155290.482: [CMS-concurrent-mark: 4.268/4.275 secs] [Times: user=40.27 sys=1.78, real=4.27 secs]
 (concurrent mode failure): 13965759K->13965759K(13965760K), 18.4763209 secs] 16496127K->14470127K(16496128K), [Metaspace: 190291K->190291K(1234944K)], 18.4769704 secs] [Times: user=43.71 sys=2.18, real=18.47 secs]

能够看到，这是因为 CMS 老年代回收并发标记时，发现老年代内存曾经有余而触发了 FullGC 强行 咋瓦鲁多，并且因为利用尽管 STW，然而申请确还是在沉积，导致始终在继续 FullGC，没有自愈

一般 CMS 老年代回收过程如下图所示。

止损和排查

止损

止损形式很简略，当然就是重启这个利用，在重启的时候利用会从注册中心里被摘掉，流量会被负载平衡到其它的服务上。重启一下，多喝热水。（PS：其实这里是能够有优化的空间的，例如某种机制发现服务在进行 FullGC 时就将其被动从注册核心中摘掉，而后待其 FullGC 结束自愈后再退出到注册核心承受申请，整个过程主动实现无需人工干预）

起因排查

问题天然要一跟到底，接下开始进行排查

为什么会 FullGC？

FullGC 的间接起因可能有以下几类：

1. 利用中被动调用了System.gc()

根本不可能是这个起因，首先没有人会闲得去调用这个办法，代码全局搜寻后也印证了这个后果了；其次就算真的有人调用了这个 System.gc() 去倡议 JVM 去反对 FullGC，咱们的服务在启动参数中开启了这个参数-XX:ExplicitGCInvokesConcurrent，这个参数的含意是将显示调用的System.gc() 转为 CMS 的并发 GC，所以并不会因而而触发 FullGC

1. 办法区（元空间）空间有余

这种个别的起因是代码中大量应用动静代理，生成了一大堆的代理类占用了办法区，如果是这个起因引起必然是所有服务都会报 FullGC 问题，然而其它机器的老年代内存很稳固，所以排查

1. 间接内存空间有余

间接内存空间有余个别是用了 nio 这样的代码导致的

1. 老年代空间有余

对象出生于新生代，在挺过了一次次 minorGC 之后胜利熬到了老年代，并且继续在老年代混吃等死，始终到大量的对象都这样在老年代混吃等死把老年代占满之后就会触发 FullGC

为什么只有一个实例异样

只有单个服务呈现了这样的问题，很有可能不是内部依赖的超时或者办法区空间有余造成，而是因为 某个刚好落在这个服务上的超大申请 占用了大量的内存并且耗时久，始终赖在老年代不走导致。

gc 日志在跟我谈话

第一次 FullGC 产生在 2020-07-25 14:51:58，察看之前的日志能够发现历史上 CMS 并发回收个别都会将堆内存稳固在3608329K->1344447K，从 3.6G 左右回收到 1.3G 左右，然而从某个工夫点开始开始 回收效率变差了。

2020-07-25T14:51:50.866+0800: 155089.417: [GC (Allocation Failure) 2020-07-25T14:51:50.866+0800: 155089.417: [ParNew: 2530368K->281088K(2530368K), 0.9268687 secs] 5001197K->3500201K(16496128K), 0.9272222 secs] [Times: user=15.37 sys=1.02, real=0.92 secs]

能够看到，这次回收从 5G 回收到 3.5G，回收完之后还有这么多被占用！这个工夫点 2020-07-25 14:51:50 左右肯定产生了什么事件，导致老年代始终保留着一批 老赖。

大搜查，找出立功嫌疑人

定位了工夫点之后，接下来的问题就是找出这个工夫点左近耗时特地离谱的大申请，好在咱们的服务有着具体的 AOP 包裹起来的申请日志，精确的记录了每个申请的相干信息，从日志中我找到了一个立功嫌疑人，申请参数长得离谱（一个申请批改了 1000 个文件夹的属性，为了暗藏公司业务逻辑以文件夹为例）。

不过光这样还不能给它定罪，因为从教训来看，这么长的申请参数其实并不常见，能够回到第一张的结构图上看，咱们的服务同时接管来自 web 和 api 两端的申请，如果是 web 上用户是没有这样的入口去操作 1000 个的，然而 api 的话是用户端写的代码，很有可能呈现这样的申请且是失常申请（咱们批量编辑的阈值刚好是 1000）。

收集证据，定罪

然而我的直觉通知我，事件没有那么简略，我又去追究了跟这个申请相干的所有日志，发现这个批改申请查问的数据多的离谱，如果只是 1000 个文件夹的话，批改只须要 3 步：

1. 依据主键 id 查出这 1000 个文件夹的属性
2. 批改这 1000 个文件夹的属性
3. 执行批改操作，提交事务

而有一个 sql 日志查问量大得离谱，暗藏掉业务逻辑后的模式如下:

select xxx, yyy from file where userid=123 and file_id in (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?...)

并且 grep 到了这个申请相干的异样栈，是执行 sql 超时触发的回滚异样 AbstractFallbackSQLExceptionTranslator.java，从异样栈中找到了 查问量大的离谱的起因

还原立功过程

原来，业务代码中做了一个这样的逻辑，原本是批改了 1000 个文件夹的某个属性，然而业务逻辑是如果批改的是某个非凡属性时，会 级联批改这些文件夹下的全副文件，文件夹和文件的关系大抵如下图

因而，实际上批改了 1000 个文件夹的申请，背地解决了 1000 个文件夹 +100w 个文件，而批改这些属性因为咱们应用的框架的限度，100w 个文件在批改前会查主属性表 + 所有辅属性表（内存依据主键 id join），申请耗时 90s，导致 大量对象 长时间 滞留在堆内存中挺过了一波波的 minorGC 和 CMS GC 干满老年代，最终触发了这个问题。

优化的思路

问题曾经定位，接下来就是问题优化的思路了：

1. 限度此类字段的批改，对于这样须要 级联 批改的状况时进行校验，不容许 API 用户传太多文件夹（1000 个 –> 100 个）
2. 微服务的思维，在该服务下层再做一个散发服务，对于这样级联批改的申请将 1000 个的批改拆成 10 个每次批改 100 个的申请去并发申请上面的机器，均摊压力
3. 异步化队列，批改文件夹自身属性后即立即返回，后续级联批改的申请拆成 n 个放入队列，由其它服务订阅到申请后执行
4. 能有监控伎俩在利用 FullGC 时从注册核心踢掉，待 FullGC 自愈后再退出，而不是人工干预重启
5. 优化 ORM 框架，就算批改 100w 个文件的某个属性，也不须要查问出这些文件的全副属性，只查问出主表 + 须要批改的属性所在的表即可