FullGC没及时处理，差点造成P0事故

背景

上线新功能后，要多观察。如果出现不稳定性的情况，需要高优先级查清原因，避免出现更大的问题。

问题描述

部分应用出现重启

过程

• 11:58，接到报警，一个pod1三分钟内存在重启

• 12:02，pod1已经5分钟没有报警，数据已经正常恢复【有耗内存的功能，多人同时触发时，偶尔也会重启】

• 12:06，JVM监控 节点机IP: 10.10.48.116 JVM_FullGC次数，最近2分钟求平均 >= 5.0 次, 当前值5.0000 次

• 12:07，JVM监控 节点机IP: 10.10.48.116 JVM_FullGC，数据已经正常恢复

• 12:15，接到报警，pod2三分钟内存在重启告警

• 12:18，pod2和pod3三分钟内存在重启告警

• 12:20，pod2和pod3和pod4三分钟内存在重启告警

• 12:24，查看重启pod日志，发现一直在刷查询tableStore异常的日志：2022-09-01 12:24:41[16-d ][I/O dispatcher 36] WARN c.a.o.tablestore.core.utils.LogUtil - TraceId:8-1 Failed RetriedCount:1 [ErrorCode]:OTSServerBusy, [Message]:Service is busy., [RequestId]:00-e1, [TraceId]:81db-cd, [HttpStatus:]503

• 12:25，JVM监控 节点机IP: 10.10.48.117 JVM_FullGC次数最近2分钟求平均 >= 5.0 次, 当前值5.5000 次

• 12:25，从 2022-09-01 12:22:00 开始，在 0 天, 3 分钟内发生 3 次 JVM监控 节点机IP: 10.10.48.117 JVM_FullGC次数最近2分钟求平均 >= 5.0 次, 当前值5.5000 次 JVM监控 节点机IP: 10.10.48.116 JVM_FullGC次数最近2分钟求平均 >= 5.0 次, 当前值5.0000 次

• 12:28，其它业务check过，没有明显异常。除个别业务在查询tableStore时也会出现503的报错

• 12:41，申请运维同学再加两个pod。增加可用pod数

• 12:50，添加pod后，重启没有停止。

• 13:07，查看是否有OOM。没有

• 13:22，收到阿里tableStore的同学反馈，503的原因是索引查询用的索引不是覆盖索引， 反查主表压力过大引起的5XX错误

• 13:23，把涉及的查询的定时任务都停掉

• 13:30, JVM_FullGC和pod重启告警 没有停止

• 13:40，看到是full GC告警，增加Pod和JVM堆内存各4G,并重新发版

• 13:42，重新发版完成。JVM_FullGC和pod重启告警都消失

• 14:00，把之前停止的定时任务启动

服务不稳定状态时堆内存及GC情况

故障原因

出现占用大内存的操作，导致FullGC频繁。

原因分析

• 是不是TableStore的异常导致服务异常

不是。看查询报错的请求低于12%

ots的报错情况

• pod为什么会重启

Full GC耗时过长，导致容器判定pod异常，并将其重启。

异常期间，pod存活探测的规则如下：

livenessProbe: # 存活探测的相关配置如下
httpGet:
path: /ready
port: http
initialDelaySeconds: 180
periodSeconds: 10 # 每隔10s探测一次
timeoutSeconds: 1 # 如果/ready接口1s内没有返回，则判断失败
successThreshold: 1
failureThreshold: 3 # 连续失败3次，则判断pod异常。容器重启pod

FullGC时会STW，此时所有请求都会阻塞。

FullGC耗时超过30s，pod就会重启。异常期间FullGC耗时都超过120s了。按配置的规则，容器会重启该pod

FullGC超过30s，则容器会将pod重启

• 为什么会触发FullGC

出现了耗内存的操作。

TableStore服务器返回的数据，占用大量内存

新加的查询TableStore的业务线程

• 上述业务占用内存是否合理

不合理。从业务上看，每次查询符合条件的记录最多不会超过100条。但现在返回了131262条

返回的数据量过多

核对过代码，发现查询条件错误。查询tableStore的三个条件应该是and的关系，但现在是or

• 这么严重的逻辑错误，为什么会出现

存在错误逻辑是2020年上线的老代码。写新功能的同学，直接copy过去。想着是两年前的线上代码，code reivew就没有作为重点，具体过程，相关的同学都不记得了。

• 这么严重的逻辑错误，为什么之前服务没有出现这种问题

之前的服务也是有问题的。

老代码由一个定时任务触发。只是串行查询TableStore，虽然会耗内存，但如果正在执行的pod没有其它在执行的耗内存操作，是不会触发FullGC的。

这也可能是当前应用偶发出现重启的原因。

新业务场景是接收到mq消息然后根据条件去触发这段老代码，当同时接收n个消息，则占用的内存*n ，则很容易触发FullGC

• 新功能上线快1周了，为什么今天才触发此异常

在查询TableStore，需要满足条件才会触发有异常的老代码。异常时，触发异常逻辑的的业务数据较多。

• 测试环节为什么没有发现

case没有全部覆盖业务场景。

当三个and的筛选条件被错写成or，查到的数据会变多。

目前的这个场景所涉及到的查询结果数据，被用于数据权限控制，返回的数据变多时造成的问题是，该看到该数据的人可以看到，不该看到该数据的也可以看到。

如果测试case只有一个：该查看数据的人是否可以查看。那么，测试是通过的。

小结

• 异常出现时，一象限的操作

如果pod重启时，是qps增高，则优先增加Pod

如果pod重启时，识别到FullGC耗时过长，则优先考虑增加内存来解决

出现异常时，要把jvm堆内的数据dump出来。在没有找到异常原因时，要把dump出来的堆数据都查看一下，因为dump时，有的pod中的jvm可能刚启动不久，异常操作还没有被触发。

• 异常出现后，二象限的操作

已经在线的代码，如果新功能涉及到，尽量不要copy

已经在线的代码，如果新功能涉及到，也要CodeReview

待上线的代码，要测试充分

待上线的功能，关键路径，测试Case要全面

增加jvm堆内存的告警，如果超过80%时就告警，然后dump出Heap内的数据进行分析

每个迭代确保用于技术优化的时间。目前这部分有一个bug需要解决：当前的规则中，需求的优先级是由产品决定，一个技术需求如果产品把优先级降低，如果引发故障，产品却不需要承担责任。需要推动这个事情解决，保持权责利一致，做多大的决定，就需要负多大的责任，也享受多大的利好。