一个 Bug 改了三次,汗流浃背了。。

2024-07-31 14:48:08 浏览数 (2)

昨天是个汗流浃背的周一,我们的后端服务竟然在一天内三次不可用,最长的一次达到了四十分钟!到底发生了什么?且听我细说。

在每周例行的需求评审会后,我就开始对我的需求进行排期,规划这周要做的工作,当我开始着手规划时,突然发现线上服务有几个没人发现的后端小 bug,于是我开始了悄无声息的改 bug。正当我改的上头时,同事小 y 突然喊我:线上怎么访问不了了!

我猛然一惊,我擦,不会是那几个小 bug 给线上干崩了吧?但是转念一想应该也不是,我赶紧放下手上的工作,开始排查线上服务。

第一次排查

定位问题

1、登录网站,确认问题

我赶紧先登录我们的网站,发现确实访问不了。打开网络控制台发现前端的资源响应很快:

而后端却一直在 pending,如图:

2、登录容器平台,查看后端服务状态

由于我们的后端部署在云托管容器平台,于是我下意识的先去平台查看服务的状态,发现我们服务的平均响应竟然达到了 21 秒!

然后我合理推测肯定是 qps 猛增,结果发现,qps 很稳定,再看看内存、CPU 占用都还算平滑:

3、登录接口监控平台定位具体问题

此时我已经发觉事情不太对,既然 qps、内存、CPU 都还算正常,那怎么接口响应这么慢?不过我们后端服务接入了某云服务商的应用实时监控服务,我赶紧进入控制台查看详细的数据,一进去就发现平均每分钟的响应时间达到了 16.2s:

此时我的心理:

但是很快我镇定下来,我要一点点排查到问题所在,正好这个接口监控平台提供了这些监控,我就一个一个点进去看都有啥问题。

4、查看 jvm 监控

于是我赶紧打开 jvm 监控定位下问题,我直呼好家伙,怎么每隔五分钟 FullGC 一次?因为每次 FullGC 都会暂停应用程序的执行,这么频繁的 FullGC 显然是有问题的,怪不得线上接口一直无法访问。

5、查看线程池监控

但是光看 jvm 监控也定位不到问题,我需要赶紧找到 FullGC 的根本原因,于是我点开了线程池监控,好家伙,这 TM 所有的线程全都上场了,甚至还有一堆在排队的。。。

这是我更不能能理解了,到底是什么阻塞了所有的线程?

6、 查看数据库连接池监控

带着疑问,我又打开了数据库连接池监控,好家伙,什么鬼?为什么连接池满了?

解决问题(bushi)

看到数据库连接池全部爆满,我就知道肯定是在查数据的时候,所有的请求都在等待连接池空闲,也就导致线程全部阻塞,最终导致频繁 FullGC,但是也不合理,因为所有的数据库请求按理来说都会自动释放掉链接呀,为什么连接池会满呢?但是这时候线上事故已经发生很久了,我得先让用户能访问网站再说,要不然用户还不得骂死我,我赶紧在 Spring Boot 的 application.yml 中配置数据库连接池的最大容量为 20,如下:

代码语言:javascript复制
spring:
  hikari:
    maximum-pool-size: 20

然后发布到线上,很快线上就可以正常访问了,使用很丝滑~

第二次排查

我本来也以为事情告一段落,可以继续修我的 bug 了,顺便我还跟同时吐槽了一波,hikaricp 就是不好用,回头要是有机会一定得换成 druid,还能监控 sql、防 sql 注入之类的。。。刚吐槽着,同事小 y 又高呼:线上又卡住了,又不行了,快去看看!

我心里一沉,好家伙,不给我喘息的机会是吧,我赶紧去看看数据库连接池监控:

怎么回事?20 个连接都不够用?这不对吧?到底是谁一直占着连接不放手!于是我赶紧进入容器平台的 webshell,使用 jstack 看看是哪个线程卡死了,发现都是 TIMED_WAITING,好吧,并不能代表什么,和我第一次排查问题时查看的线程池监控的结果一致。

暂时没有找到根本原因,但为了线上能继续访问,我只能先把这些问题抛之脑后,重新发布一版,把连接池清空掉重新来。

第三次排查

这次我老实了,感觉这不是我能处理得了的 bug,赶紧请上我们团队的技术大佬 yes 哥,我把情况大概给 yes 哥说明了一下:我们线上的连接池总是被很快的耗尽,但是排查不到是哪个地方占用了连接不释放。yes 哥立马就反应过来:慢 sql 你排查了吗?我一惊,好像没排查。。。

定位问题

这次,我直接查看慢 sql,果然有个慢 sql 执行了七千多次,而且平均时间居然达到了 1.4 秒,这连接池根本没有闲着的时候啊!

分析问题

再仔细看下这个 sql,发现 scene 这个字段没有加索引,也就是说每次这个请求都会走一遍全表扫描,然后我看了下这个 sql 执行的场景,是在微信公众号扫码登录时,前端轮询用户是否已经扫码并关注公众号,如果扫码关注了公众号则登录成功。大致的流程如下:

那么很显然,我们的问题就出在后端根据场景码轮询用户信息这里,这里有个慢 sql,因为我们的 scene 没有设置索引,因此导致每次查询用户是否扫码登录时都要进行全表扫描,用 explain 看下这个 sql:

解决问题

但是当时我比较犹豫,因为加上这个字段后,大概率只会命中一次,只要有一次查到了,这个 scene 就无效了,所以我总感觉这个索引加了会浪费性能。我跟 yes 哥表达了我自己的想法,但是 yes 哥的想法是,就算他只有一次生效,至少不会在轮询的时候一直扫全表,毕竟这个 sql 是前端轮询的产物。

我想了想有道理,这时候,我们老板出来了(也就是鱼皮):怎么回事,你们在讨论什么?!线上服务不可用都已经四十多分钟了,还不先把服务恢复了再讨论详细解决方案?

于是我赶紧按照 yes 哥的方案,把这个索引加上了,让我没想到的是,效果立竿见影,线上一下就可用了,看下连接池的变化:

此时我长舒了一口气,终于算是搞定了,这时候我再 explain 一下,发现这时候已经是走索引了:

好吧,我为我的无知向 hikaricp 道歉,不是你的锅,是我的锅~

后来我又查了下阿里巴巴的 Java 开发手册,发现这本手册第五章中的第(二)节里明确写了创建索引时要避免的误解,如下图:

我就是因为第二点认为索引不应该随便创建,因为可能会导致拖慢记录的更新之类的,后来想了下,其实 user 表的更新并不频繁,包括这个 scene 的更新也不频繁,因为用户在正常使用过程中又有几次会重新触发登录呢?

好了,汗流浃背的周一就这么度过了,算是长了个记性,赶紧把所有的慢 sql 都看一下,能加索引加加索引,不能加索引的,看看能不能换个实现方式。以后排查问题又多了个思路,线上的连接池用完了要先排查下有没有慢 sql 导致链接一直没被释放,再往下排查。

鱼皮总结

通过这次事故,暴露了我们开发同学经验的不足。

  1. 遇到服务卡死问题时,赶紧先扩个容新增一台可用实例,然后再对着原有故障实例的现场进行排查。
  2. 时间紧迫的情况下加大数据库连接数没问题,但是才加了 10,显然是有点太保守了,我们的数据库还是扛得住的。
  3. 应该能够预料到问题并没有根本解决,并且赶紧继续观察和排查,怎么就开始做别的了呢?
  4. 排查定位问题的效率不高,像 “如何定位线程池爆满问题” 这种八股文知识还是要背背的。

而且我在 上一篇文章 中也提到了,导致本次故障的慢 SQL 我们早就发现并且发到群里了,结果团队几个开发竟然没一个人去处理。。。

当然,最遗憾的是,这篇写出来的事故复盘仍然是残缺的!

现在的这个解决方案并不完整,在我看来还是 临时 解决了这个问题。信不信,并发量再大点,系统的某个地方还会出现类似的问题?难道到时候再汗流浃背一次?俗话说事不过三,这次的损失我们忽略不计,下一次可就不一定了。

既然我们用了可以根据资源利用率自动扩容的容器平台,那么当并发量增大、单个节点处理不过来时,就应该自动扩容,自然能够应对更大的并发请求。通过本次事故,我们发现请求连接数满的时候,节点的 CPU 利用率才不到 20%、内存才不到 60%,根本达不到扩容的阈值。所以应该适度增大数据库连接池数量、增大服务器请求处理线程的数量,提高系统资源利用率,并且通过压力测试来验证能否触发自动扩容。或者调整容器的扩容策略,也是一种方案。

0 人点赞