问题的产生

简略介绍下咱们服务的背景，咱们的服务是一个应用相似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个文件的某个属性，也不须要查问出这些文件的全副属性，只查问出主表+须要批改的属性所在的表即可