记一次P0bug问题排查流程

问题影响

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

排查流程

表现

时间

2021-09-15 10:50 am

问题表象

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

2. sentry 发出大量错误日志

都是同一个项目 general

排查方法

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

1. 确认最近的修改

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

1. 上线的项目

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

2. 改过的配置

没有直接影响

3. 报错日志

无法定位问题

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

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

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

2. 判断代码&项目问题

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

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

1. 查看容器节点

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

2. 关注grafana

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

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

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

慢日志还挺多

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

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

4. 找人问最近上线事宜

在第一步中，我们找到最近上线的负责人， 因为他们上线时增加了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了