性能文章>FullGC没及时处理,差点造成P0事故>

FullGC没及时处理,差点造成P0事故原创

2月前
308745

背景

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

问题描述

部分应用出现重启

过程

  • 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,把之前停止的定时任务启动

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

故障原因

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

原因分析

  • 是不是TableStore的异常导致服务异常
  • 不是。看查询报错的请求低于12%

image2.png
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

image3.png
FullGC超过30s,则容器会将pod重启

  • 为什么会触发FullGC
    出现了耗内存的操作。

image4.png
TableStore服务器返回的数据,占用大量内存

image5.png
新加的查询TableStore的业务线程

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

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

image6.png
返回的数据量过多,核对过代码,发现查询条件错误。查询tableStore的三个条件应该是and的关系,但现在是or。

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

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

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

之前的服务也是有问题的。老代码由一个定时任务触发。只是串行查询TableStore,虽然会耗内存,但如果正在执行的pod没有其它在执行的耗内存操作,是不会触发FullGC的。这也可能是当前应用偶发出现重启的原因。

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

  • 新功能上线快1周了,为什么今天才触发此异常
    在查询TableStore,需要满足条件才会触发有异常的老代码。异常时,触发异常逻辑的的业务数据较多。

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

case没有全部覆盖业务场景。当三个and的筛选条件被错写成or,查到的数据会变多。目前的这个场景所涉及到的查询结果数据,被用于数据权限控制,返回的数据变多时造成的问题是,该看到该数据的人可以看到,不该看到该数据的也可以看到。

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

小结

  • 异常出现时,一象限的操作
  1. 如果pod重启时,是qps增高,则优先增加Pod
  2. 如果pod重启时,识别到FullGC耗时过长,则优先考虑增加内存来解决
  3. 出现异常时,要把jvm堆内的数据dump出来。在没有找到异常原因时,要把dump出来的堆数据都查看一下,因为dump时,有的pod中的jvm可能刚启动不久,异常操作还没有被触发。
  • 异常出现后,二象限的操作
  1. 已经在线的代码,如果新功能涉及到,尽量不要copy
  2. 已经在线的代码,如果新功能涉及到,也要CodeReview
  3. 待上线的代码,要测试充分
  4. 待上线的功能,关键路径,测试Case要全面
  5. 增加jvm堆内存的告警,如果超过80%时就告警,然后dump出Heap内的数据进行分析
  6. 每个迭代确保用于技术优化的时间。目前这部分有一个bug需要解决:当前的规则中,需求的优先级是由产品决定,一个技术需求如果产品把优先级降低,如果引发故障,产品却不需要承担责任。需要推动这个事情解决,保持权责利一致,做多大的决定,就需要负多大的责任,也享受多大的利好。
  • 待解决的问题
  1. FullGC耗时过长的原因及解决办法
点赞收藏
bit01
请先登录,查看4条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

JVM 常见线上问题:CPU100%、内存泄露的问题排查

JVM 常见线上问题:CPU100%、内存泄露的问题排查

【全网首发】不经意的两行代码把CPU使用率干到了90%+

【全网首发】不经意的两行代码把CPU使用率干到了90%+

【全网首发】Tablestore-OTSClient连接池连接无法复用分析

【全网首发】Tablestore-OTSClient连接池连接无法复用分析

关于SimpleDateFormat线程安全问题根因探究

关于SimpleDateFormat线程安全问题根因探究

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

【全网首发】一次想不到的 Bootstrap 类加载器带来的 Native 内存泄露分析

【全网首发】记一次MySQL CPU被打满的SQL优化案例分析

【全网首发】记一次MySQL CPU被打满的SQL优化案例分析

5
4