故障背景
案例来自于推送网关的一次线上故障。日志显示【内存使用率过高-超过95%】并实例自动重启，查看日志和apollo配置，确认应用资源限流已经触发，正常情况下的数据推送量不可能会出现内存被打满的情况，必定出现了短时间大流量的数据推送。查询得知，短时间内数据推送量达到100W，远超应用预设的最大推送量。
推送网关架构
系统现状
当前应用是一个推送网关，通过消费MQ，执行责任链将数据推送。
为了避免推送效率受mq消费线程数（mq默认20）的限制或者采用线程池但不便设置具体线程池大小（每个消息体的大小差异性极大），推送时采用apache的HttpAsyncClient（内部基于reactor模型）来执行网络请求，callback回调的方式来获取推送结果。 原限流方案是，对每个业务类型代码设置为50条message，超过50会被拒，返回给MQ稍后消费状态，间隙性去MQ重试消费被拒的消息。存在的问题：随着接入业务增多，而 所需最大资源 = 业务类型种数 * 限流数，实例有限的情况下，限流效果逐步减弱。
故障分析
模拟场景，将数据往MQ投递，观察JVM资源情况，分析原因。
当前应用资源配置情况
实例数量：1
服务实例配置：1核2g
jvm默认参数：-Xmx1g -Xms1g -Xmn512m -XX:SurvivorRatio=10 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:CMSMaxAbortablePrecleanTime=5000 -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+ExplicitGCInvokesConcurrent -XX:ParallelGCThreads=2 -Xloggc:/opt/zcy/modules/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/zcy/modules/java.hpro
先查看服务无流量基本处于闲置状态时一个情况，通过arthas dashboard查看jvm使用情况
可以看到各线程对cpu的使用率极低，基本处于闲置状态。
接着看下半部分Memory框中的信息，主要的数据项含义如下：
-
heap（堆大小）
-
par_eden_space(伊甸区大小)
-
par_survivor_space（S区大小）
-
cms_old_gen（老年代大小）
-
gc.parnew.count（young gc总次数）
-
gc.parnew.time（young gc总耗时）
-
gc.concurrentmarksweep.count（full gc总次数）
-
gc.concurrentmarksweep.time(full gc总耗时)
5S后
结合5s前的数据，我们主要关注以下指标：
- 线程情况：线程cpu使用率并没有明显变化
-
heap（堆大小）：堆使用大小增加3M
-
par_eden_space(伊甸区大小)：年轻代中的伊甸区只增加3M，按照伊甸区426M的大小，大约需要710秒（约12分钟）才会触发一次young gc
-
par_survivor_space（S区大小）：无变化
-
cms_old_gen（老年代大小）：无变化
-
gc.parnew.count（young gc总次数）：无变化
-
gc.parnew.time（young gc总耗时）：无变化
-
gc.concurrentmarksweep.count（full gc总次数）：无变化
-
gc.concurrentmarksweep.time(full gc总耗时)：无变化
接下来模拟积压数据进行推送时的场景，数据提前通过自动化脚本投递到MQ当中。
积压5000条数据
使用arthas命令 dashboard -i 1000 ， 按照5s的间隔输出，观察老年代：
5s后：
对比两次数据，关键信息如下：
- 5s之内（gc.parnew.count）发生了510-503 = 7次young gc
- 老年代（cms_old_gen）由233m增长至265m，增长了32m左右，按照老年代512m的大小，大约80s就会发生一次full gc
积压1.5W条数据
5S后
对比两次数据，得知以下关键信息：
-
线程情况：cms垃圾回收线程cpu占用率高达45%+
-
full gc次数：5s内发生了3次full gc
-
full gc总耗时：总耗时由 14742 增加至 15131
5s之内发生了3次full gc，平均每次full gc耗时（15131-14742）/ 3 = 129 ms，虽然出现了full gc频繁的情况，还不至于造成服务不可用。
积压2W条数据
5S后
对比两次数据发现：
- 线程情况：cms垃圾回收线程cpu占用率48%+
- 老年代：已使用511m（总大小512m）
- full gc次数：5s内发生了3次full gc
5s内发生了3次full gc，老年代始终处于已使用511m（总大小512m）的情况,每次的full gc平均耗时 （81942-79740）/3=734 ms，相当于5s内有2.2s的时间都在full gc。
此时查看日志发现数据推送时发生大量的socket连接超时：
再查看下当时的gc日志
查看gc日志发现：两次full gc之间只差了1.4s左右，从524287k回收至524275k，只回收了12k的内存空间，却花费了0.7s左右时间，系统有一半的时间都在进行full gc，造成系统不可用。
原因分析
通过上面测试可以发现系统存在的问题主要是由于下游消费速率（网络请求）跟不上上游的投递速率（mq消费），导致内存逐渐被打满，系统频繁full gc造成服务不可用，直至产生OOM程序崩溃。
优化方案
在该场景中系统的主要瓶颈在于jvm内存大小上面，当前系统频繁full gc，无法及时释放内存导致内存溢出，致使整个实例挂掉。所以达到我们的目的，需要做到两点：
-
调整JVM参数，让内存回收更合理（缓解，但不治标）
-
扩大内存，满足数据洪峰的最大值（治标，但浪费资源）
-
基于jvm堆内存使用率来对上游进行限流控制（可彻底解决问题，将流量压力抛给上游MQ）。
jvm参数优化
- 原来年轻代大小设为1024M并不适用于这种数据推送场景。通过观察发现老年代常驻对象150M左右，考虑浮动垃圾等，老年代分配512M大小，所以年轻代调整为1.5g大小：-Xmn1536M
- 修改年轻代中的伊甸区和s区的比例由10:1:1修改为8:1:1，避免young gc后存货对象过多直接进入老年代： -XX:SurvivorRatio=8
- 元空间大小分配256m。-XX:MaxMetaspaceSize=256M -XX:MetaspaceSize=256M
- 线程栈最大1m：-Xss1M
- 针对年轻代使用ParNew垃圾收集器：-XX:+UseParNewGC
增加资源限流
当前推送流程是基于责任链的模式来进行设计的，所以只需在链中再增加一个限流器即可。
- 限流器中可设定一个jvm堆内存的使用率，当超过这个阈值后对当前的消费线程进行阻塞，直到使用率低于阈值后再进行放行
- 当触发限流阻塞消费者线程时，为应对特殊情况，可设置一个最大阻塞时间，超过该时间后放行该消费者线程
其中阈值的配置范围给出一个参考公式：
最大阈值百分比 = （年轻代可使用最大值 + 老年代可使用最大值 * -XX:CMSInitiatingOccupancyFraction参数值）/ 堆可使用最大值
最小阈值百分比= 年轻代可使用最大值 / 堆可使用最大值
代入相关参数，即
最大阈值百分比 = （1381 + 512*0.8 ）/ 1894 = 94%
最小阈值百分比 = 1381 / 1894 = 72%
参考代码：
方案验证
资源配置
- 实例配置：1核4g
- 实例数：2
数据量：5w条积压数据
资源限流前
现象：由于内存被打满，jvm频繁进行full gc，导致cpu被打满，数据推送线程获取的cpu时间片减少，引起网络io下降，大量请求返回socket连接超时。
资源限流后
在对jvm参数进行优化以及添加资源限流器后，再次模拟数据积压情况观察效果。
推送完成后：
结果比对
| 推送总耗时 | full gc次数 | full gc总耗时 | 单次full gc平均耗时 | |
|---|---|---|---|---|
| 优化前 | 约35分钟 | 312 | 309232 | 991ms |
| 优化后 | 约18分钟 | 104 | 45387 | 436ms |
对比优化前后，使用新的限流方案后的效果显著的，性能提升近了一倍。并模拟导致线上故障的情况，通过脚本将100W数据量推送MQ后，服务正常运行。
感谢你读到这里，不如关注一下？👇
