记一次 P0 bug 修复

问题影响

今天早上 10:50 左右，系统页面突然不能访问，我们是 sass 系统，很多租户爆出了同样的错误。问题影响到了租户的使用。

排查流程

表现

时间

2021-09-15 10:50 am

问题表象

1. 多个租户素材列表页不显示内容

1. sentry 发出大量错误日志

都是同一个项目 general

排查方法

由于从报错日志中无法定位业务代码，所以采用相关度排查。

1. 确认最近的修改

早上 10:50 左右开始， 从此时间开始推导该时间前后

1. 上线的项目

昨晚是有一个项目上线，但是目前没有发现影响

1. 改过的配置

没有直接影响

1. 报错日志

无法定位问题

1. 数据量是否有较大变化

新租户 t247 上线了 80w 新素材，可能会对系统产生压力。

以上无法直接或间接得出结果

1. 判断代码&项目问题

general 模块报错， 但是从报错日志，无法确认是代码逻辑问题导致的错误。

一开始想找运维重启 general 项目，但是运维告知项目已经自动重启 6 次，重启无法解决问题。

1. 查看容器节点

正如运维所说 general 项目在不断的重启， 重启是因为节点的健康检查机制， 连续 5 次 3s 内健康检查请求得不到反馈，容器自动重启。 但是重启后最大请求时间还是居高不下。后来运维关闭健康检查机制。 奇怪的是关闭健康检查机制之后，系统莫名的正常了。但是没有找到正确答案，还是不能放松警惕。此时时间是 11:25 am 左右。

1. 关注 grafana

发现请求最大时长可以达到一分半，这个就绝对不正常了。怪不得容器不停重启，肯定是因为请求堵塞了，所以健康检查接口无法得到结果。

1. 定位请求慢原因（慢 SQL ）

当时项目 CPU 正常，内存正常，垃圾回收正常。 于是将问题归纳到数据库上，联系运维拉取慢日志。慢日志拉下来了。

慢日志还挺多

在茫茫日志中，有一个熟悉的数字 t247， 而且不止出现一次。这个 SQL 执行了 49s 。

当然一个 49s 的慢 SQL 不至于把系统整瘫。

1. 找人问最近上线事宜

在第一步中，我们找到最近上线的负责人， 因为他们上线时增加了 80w 数据，而慢 SQL 与数据量也有很大关系。仔细一聊，我们发现了一个要命的问题：前端有个页面，某个接口在会每隔 10s 请求一次 general，而且这个接口很慢。于是我打开了 grafana， 一遍复现这个请求，一遍观察请求速度。不出所料，的确很慢。 随后安排了这个逻辑修复。

为什么健康检查关闭就好了？

由后续的检测可以得知：慢 SQL 是拖垮 general 项目的原因。如果 genenral 项目能恢复，那么原因就是慢 SQL 任务执行完毕了。

在观察慢 SQL 日志时，我发现关闭健康检查的同时（ 11:25 am ），关于 t247 租户的慢 SQL 锐减。这基本上就能确定慢 SQL 的锅了。

总结

首先遇到较难问题不要慌，积极应对。多个人多份力量，一起分析。

可以按照上面的排查方法一步一步来。

1. 查看各个指标监控

• sentry 项目检测
• k8s 重启次数
• Grafana 性能指标
• 数据库 CPU&内存指标
• 慢 SQL 检测

1. 确认最近的修改

2. 代码与项目状态排查

3. 针对代码或者项目进行分析

4. 拉通第一步中人员进行一起分析

基本上通过这几步问题大致能够定位问题所在，剩下 20%的工作量就是修复 bug 了