万恶的Scan,30万单就这样没了...

开发 前端 开发工具
昨天晚上下班回家,在地铁上,老大突然打来电话,B 系统生产环境响应缓慢,影响了 A 系统的使用,几万小哥收不了单,大概有 30 万单卡住了,你去帮忙定位一下。

 [[385025]]

图片来自 Pexels

我 8 点半左右到家,立马上线入会......

重启

我入会的时候,已经有同事在帮忙定位了,俗话说的好,重启能解决 80% 的问题,如果重启解决不了,那肯定是重启的次数还不够,呸,不对,重启解决不了,就真的要去定位了。

事实证明,重启后走一波压测依然没什么用,1000 个并发,平均响应时间在 3~4 秒,连续压了几次都是这样的结果。

升级配置

重启看来是无效了,进入第二个阶段——升级配置,2 台 4 核 8G 的实例升级到 6 台 8 核 16G,数据库的配置也翻了一倍,能用钱解决的问题,我们一般不会投入太多的人力!

事实证明,加配置也没什么卵用,1000 个并发,压测的平均响应时间还是在 3~4 秒。

有点意思,此时,我介入了。

查看监控

我上线之后,查看了一下监控,实例的 CPU、内存、磁盘、网络 IO、JVM 堆内存使用情况好像都没啥问题,这真是个头疼的问题。

本地压测

我们分成两波同学,一波去准备本地压测,一波继续分析,经过本地压测,我们发现,本地环境,单机,1000 个并发,妥妥的,毛问题都没有,平均响应基本维持在几百毫秒。

看来,确实跟服务本身没有问题。

代码走查

实在没有办法了,拿出代码,一群大老爷们一起看代码,研发同学给我们讲解业务逻辑,当然,他已经被各位大佬给骂死了,写的什么破代码。

其实,在我介入之前,他们已经改过一波代码了,有个地方把 redis 命令 scan 改成了 keys *,这里埋了个坑,但是,现在不是主要问题,后面我们会说。

代码一路走读下来,发现有很多的 redis 操作,还有个 for 循环里面在调 redis 的 get 命令,其他的都是常规的数据库操作,而且都加了索引的。

所以,初步排查,数据库这里应该是没有什么问题,主要问题可能还是集中在 redis 这块,调用太频繁了。

加日志

代码走查下来,除了那个 scan 改成了 keys *(这个我还不知道),基本上没有什么问题,加日志吧, 一小段一小段的加上日志,OK,重启服务,压测来一波。

当然了,结果没有什么变化,分析日志。

通过日志,我们发现,调用 redis 的时候时而很快,时而很慢,看起来像是连接池不够的样子,也就是一批请求先行,一批请求在等待空闲的 redis 连接。

修改 redis 连接数

查看 redis 配置,用的是单机模式,1G 内存, 连接数默认的 8,客户端还是比较老的 jedis,果断改成 springboot 默认的 lettuce,连接数先调整为 50,重启服务,压一波。

平均响应时间从 3~4 秒降到了 2~3 秒,并不明显,继续加大连接数,因为我们是 1000 个并发,每个请求都有很多次 redis 操作,所以,肯定会有等待,这次我们把连接数直接干到了 1000,重启服务,压一波。

事实证明,并没有明显地提升。

再次查看日志

此时,已经没有什么好的解决办法了,我们再次回到日志中,查看 redis 相关操作的时间,发现 99% 的 get 操作都是很快返回的,基本上是在 0~5 毫秒之间,但是,总有那么几个达到了 800~900 毫秒才返回。

我们以为 redis 这块没什么问题了。但是,压测了好几次,时间一直提不上去。

很无奈了,此时,已经半夜 3 点多了,领导发话,把 XX 云的人喊起来。

云排查

最后,我们把 XX 云相关的人员喊起来一起排查问题,当然,他们是不情愿的,但是,谁让我们给钱了呢!

XX 云的负责人,把 redis 的专家搞起来,帮我们看了下 redis 的指标,最后,发现是 redis 的带宽满了,然后触发了限流机制。

他们临时把 redis 的带宽增大三倍,让我们再压测一波。握了颗草,平均响应时间一下子降到了 200~300 毫秒!!!!

真的是握了颗草了,这就有点坑了,你限流就算了,带宽满了也不报警一下的么......

这真是个蛋疼的问题。到这里,我们以为问题就这样解决了,领导们也去睡觉了!

上生产

既然问题原因找到了,那就上生产压一波吧!我们让 XX 云的专家把生产的带宽也增大了三倍大小。

从生产提交拉一个 hotfix 分支,关闭签名,重启服务,压测走一波。完蛋,生产环境更差,平均响应时间在 5~6 秒。

测试环境我们是改了连接池配置的,生产环境还是 jedis,改之,走一波。并没有什么实际作用,还是 5~6 秒。

真是个蛋疼的问题。

查看监控

查看 XX 云中 redis 的监控,这次带宽、流控都是正常的。

这次不正常的变成了 CPU,redis 的 CPU 压测的时候直接飙到了 100%,导到应用响应缓慢。

再次唤醒 XX 云 redis 专家

已经凌晨四点多了,大家已经没什么思路了,XX 云的 redis 专家,你给我再起来!

再次唤醒 XX 云的 redis 专家,帮我们分析了下后台,发现 10 分钟内进行了 14 万次 scan......

万恶的 scan

询问研发人员哪里用到了 scan(前面他们改的,我不知道),发现,每次请求都会调用 scan 去拿某个前缀开头的 key,每次扫描 1000 条数据,查看 redis 键总数,大概有 11 万条。

也就是说,一个请求就要 scan 100 次,1000 并发,大概就是 10 几万次 scan。

我们知道,redis 中 scan 和 keys * 是要进行全表扫描的,非常消耗 CPU,14 万次 scan 操作,直接让 CPU 上天了。

为什么测试环境 CPU 没有上天呢?

对比了下,测试环境和生产环境 redis 的键总数,测试环境只有 900 个 key,每次请求也就 scan 一次或者 keys * 一次,毛线问题都没有。

为什么生产环境有这么多 key?

询问研发人员,为什么生产环境有这么多 key,没有设置过期时间吗?

研发人员说设置了的,是另一个同事写的代码,打开代码,真是一段魔性的代码,具体代码我就不方便贴出来了,里面有根据条件判断要不要设置过期时间,经过分析,大部分情况下,都没有设置过期时间成功。

当前解决办法

此时,已经凌晨 4 点半了,虽然大家还很兴奋,但是,经过领导决策,暂时先不动了。

因为,目前 A 系统已经暂停调用 B 系统了,所以,此时 B 系统可以说流量几乎为 0 了。

我们白天再分两个阶段来修复这个问题:

  • 第一步,先清理掉生产环境 redis 的数据,只保留一小部分必要的数据。
  • 第二步,修改 scan 某前缀开头的数据,改成 hash 存储,这样可以减少扫描的范围。

好了,本次生产事故排查就到这里了。

总结

本次生产事件跟以往遇到的事件都略有不同,大概总结一下:

  • 以往都是应用服务本身的 CPU、内存、磁盘、JVM 这些问题,redis 的带宽和限流还是第一次遇见。
  • 上了 XX 云以后,很多东西还没有弄得熟练,包括监控指标这些,还需要慢慢摸索。
  • redis 一定要禁用掉 keys 和 scan 命令,且大部分 key 应该设置过期时间!

好了,本次事件大概就写这么多,后续有新的情况我也会继续跟进的,当然,最好不要有新的情况!

作者:彤哥

编辑:陶家龙

出处:转载自公众号彤哥读源码

 

责任编辑:武晓燕 来源: 彤哥读源码
相关推荐

2020-09-25 07:57:42

生产事故系统

2013-04-12 09:58:16

2022-09-07 09:45:19

TypeScrip开发者

2014-04-25 09:43:54

2022-06-09 11:51:05

YODA工具恶意插件

2011-01-05 16:19:34

2012-02-02 14:35:08

程序员

2016-11-21 21:28:51

根目录日志代码

2013-12-31 09:19:23

Python调试

2020-12-29 10:56:38

恶意软件SoReL-20M网络安全

2015-03-30 09:26:24

JavaScriptHTML6

2020-09-14 16:27:51

机器人AI人工智能

2014-09-16 10:05:39

职场年薪

2013-07-05 09:59:23

2009-12-03 15:06:51

Suse修改主机名

2015-05-13 10:42:21

程序员代码

2021-01-24 10:21:56

比特币区块链加密货币

2010-05-04 15:39:44

IT人才

2018-04-26 14:59:23

面试AndroidService

2015-04-16 09:48:12

APP测试
点赞
收藏

51CTO技术栈公众号