简述
唉,小趴菜我最近又犯事了,怎么会是捏?
事情是这样的,618后业务量回落,业务应用大量缩容,Redis集群呢也要跟着缩容,但是在晚上22:00进行缩容运维操作的时候,突然导致业务访问Redis大规模超时,此后经过重启短暂恢复,但又在凌晨00:00到01:30再次触发大规模Redis访问故障,当我收到业务的电话轰炸和告警通知时,人已经麻了。。
痛定思痛,总结下来我觉得这次故障还是比较有价值的,至少是自己接手Redis以来的第一次大规模事故(痛心ing,绩效没了),下面就开始讲述这一次我遭遇的血的教训!
故障时间线
伏笔
在正式开始之前,我先埋一个伏笔。😀
在618开始之前,为了应对业务高峰而扩容了Redis集群,最多的Redis集群机器数量超过100多个,这时由于集群规模过大,因而发生了cluster nodes慢查询的问题,为了排查这个问题,我在一个集群里手动加入了两个新节点用于测试Redis6对cluster nodes命令的优化,我成功完成了验证Redis6确实有效,但今天的主题不是这个。。
一般来说加入新节点都是通过我们开发的web端Redis管理平台加入的,但谁能想到这次手动加入却成为了十几天后这次故障的伏笔...
第一次故障
时间 | 现象描述 |
---|---|
22:31:00 | 缩容时需要将数据从待下线节点迁移到集群内其他节点上,这时数据迁移完成 |
22:35:00 | 停止从节点的Redis进程 |
22:39:00 | 开始下线第一个主节点,这时业务开始报错! |
第一次故障的现象是下线第一个主节点后业务开始报错,具体报错是超时报错,由于Redis缩容导致短暂的缓存访问超时是预期内的,决定先观察再决定后续操作。
但观察1min后异常仍然没有停止的迹象,为了及时止损,先手动重启(第二个伏笔)了这台下线的主节点Redis进程,此时业务异常恢复。
松了一口气的我正要排查原因时,突然业务反馈Redis查询99线变高了!我一开始还不信,亲自确认后发现确实999线达到了100多ms,平时这个时间最多2ms。
所以原因是什么呢?
我一时半会没想到😢,联系了组内其他同事一起看,也没有找到原因,因此决定将集群完全恢复到缩容之前的状态。。。
第二次故障
没错,只要恢复到缩容之前的状态一切都会好起来的!👌
于是我们先决定将数据迁移回那些准备下线的Redis主节点上,我们在内部的Redis管理端操作迁移。但是一迁移问题就出现了,**又是大量业务报错,甚至比第一次更多!**看到CAT上大量的红盘我的心拔凉拔凉的。。。
我们紧急停止了迁移,但是报错竟然没有停止,还在疯狂报错,分析具体报错发现不是超时报错,而是MOVED异常,和之前的 MOVED异常不同(详见:记一次Redis迁移Slot引发的故障 (deadlock.cloud)),这次报错的量很多,而且停止迁移后仍然在报错。
进一步分析发现MOVED异常是有规律的,具体来说基本上集中在两个ip,slot是10234,假设这两个ip分别为ip1和ip2,那么报错就类似于:
moved ip1 10234 moved ip2 10234
我们立即查看了到这两个ip上查看集群拓扑(通过cluster nodes命令),果然发现了问题,在ip1上查看10234的归属确实是ip2,然而在ip2上查看10234的归属竟然是:
arduino
代码解读
复制代码
86107b968a281aedbcddd9267b53dfb4bcaadee4 ip2:6379@16379 myself,master - 0 1716880618000 80 connected ... [10234-<-9a1be71bd5699ecb62b4308212ba1363ea72020f] 9a1be71bd5699ecb62b4308212ba1363ea72020f ip1:6379@16379 myself,master - 0 1716880619167 74 connected ...
原来如此!在ip2上查看10234的状态竟然是迁移中!
而且源节点就是ip1,那么怪不得有报错了:只要查询10234上的key的请求,大部分都会路由到ip2,但是ip2又会返回MOVED ip1,然后客户端再访问ip1,ip1又重定向到ip2,如此循环,超过5次(Lettuce的默认配置)就会报错。😵
那么问题来了,为什么slot的状态不对呢?
这时候我们没有时间详细排查,业务全炸了((⊙﹏⊙)还好是半夜)
所以我们通过在ip2上执行cluster setslot命令先将10234的归属设置为自己,然后再观察业务报错,果然在执行命令之后全部恢复了。 终于松了一口气,但是当我们确认业务访问Redis的999线是否正常时,居然又给我当头一棒:业务的999线仍然没有恢复,还是超过100ms!
这时我终于傻了,为什么呀?😂
999线仍然很高的原因是什么?
在查看cluster nodes命令输出时发现一个盲点:我们发现了已经下线的从节点仍然在cluster nodes的输出中,而且状态是handshake! 为什么已经下线的节点还会出现在集群拓扑中呢?
来不及细想,我们怀疑这很可能就是999线升高的原因,怀着瞎猫碰着死耗子的心态,我重启了已经下线的从节点进程,然后奇迹发生了,999线居然真的恢复了!!!
历时3个小时,从22:30开始的故障持续到1:20,心力交瘁的我仍然无法入睡,比起明天来自领导的质问,此时萦绕在我心头的是两个问题:
- 为什么999线会升高?handshake状态的节点会和这有关系吗?
- 为什么迁移slot的时候会出现slot分布不一致的情况?
事后分析
slot分布不一致的原因
冥思苦想得不出结果,我重新梳理了slot迁移的各个步骤:
- 首先要在源节点上设置slot的状态为migrating,在目标节点上设置slot的状态为importing
- 开始迁移,使用migrate命令
- 迁移完成,给所有集群中的master节点发送
cluster setslot {slot} node {nodeId}
,这里的nodeId就是目标节点的slotId,这个命令的目的是确立slot的最终归属
好的回到我们的问题,为什么会出现第二次故障时,目标节点的slot状态不对?
这就到了伏笔二出场的时刻了,还记得当初是怎么重启下线的主节点的?手动! 为什么手动会出现问题?
整理了一份好像面试笔记包括了:Java面试、Spring、JVM、MyBatis、Redis、MySQL、并发编程、微服务、Linux、Springboot、SpringCloud、MQ、Kafka 面试专题
需要全套面试笔记【点击此处即可】免费获取
因为我们是在管理端操作迁移的,管理端会自动进行上述1~3步骤命令的发送,但是却没有给手动重启的节点发送!因为出手动重启的节点已经在管理端下线,只是手动重启导致管理端并不知道节点已经重启了,发送setslot命令并没有发送给出问题的节点!所以导致slot的状态一直没有更新。。
好的,第二个问题的解释如此苍白,但总算有了解释!
现在来分析第一个问题:为什么999线会升高? handshake状态的节点会和这有关系吗? 这其实是两个问题,我们分开来说。
handshake状态的节点从哪来的?
首先解释为什么会出现handshake状态的节点?
handshake节点是刚加入到集群的状态,还没有完成ping-pong的交互,而且进一步细看,这些节点全部都是已经下线的从节点!
我再次确认了从节点上已经没有Redis进程了,可为什么已经下线的从节点还会出现集群中?
首先我们要了解Redis集群节点下线需要做什么:
- 如果是主节点,需要将其拥有的slot迁移到其他节点,然后对集群内其他节点执行cluster forget {nodeId}
- 如果是从节点,则对集群内其他节点直接执行cluster forget {nodeId}
注意“对集群内其他节点直接执行cluster forget”这个动作需要在60s内发送完成,其原因是:
当节点接收到CLUSTER FORGET node-id命令后,会把node-id指定的节点加入到禁用列表中,在禁用列表内的节点不再发送Gossip消息。禁用列表有效期为60秒,超过60秒节点会再次参与消息交换。也就是说第一次forget命令发出后,需60秒内在集群各节点上执行forget命令
所以为什么会出现handshake?
这个问题随着slot迁移不一致问题的解决也得到了提示,这时是时候揭晓伏笔一了:之前我没有通过管理端而是手动添加了两个节点到集群中!
那么这两个节点肯定没有接收到cluster forget命令!导致其在集群内部不断传播这两个节点的gossip消息。
完了吗?还没有!
999线升高的原因
好的handshake的问题解决了,可为什么业务访问999线会升高呢?
这里我详细观察了业务访问Redis耗时变高的时间点正好和集群内部cluster nodes命令突然变高的时间点吻合!
而且cluster nodes命令呈现出周期性尖刺的形式!那也就是说很可能是业务客户端在同一时间调用cluster nodes命令造成Redis短时间阻塞,但为什么cluster nodes变得频繁了?
cluster nodes是Lettuce客户端用来刷新集群拓扑的命令,而触发集群拓扑刷新有几个条件:
拓扑刷新机制 | 触发时机 | 约束条件 |
---|---|---|
onAskRedirection | 执行 Redis 命令时候,Key 所在 SLOT 正在迁移数据 | 默认 30 秒内已经刷新过,则跳过刷新 |
onReconnectAttempt | ConnectionWatchdog 监听到 channelInactive,立即触发延迟重连,默认最多重连 5 次延迟提交机制 | |
onUncoveredSlot | 客户端创建 Redis 连接时,找不到 SLOT 或者 Host/Port 对应的 partition 信息 |
对于第一个“执行 Redis 命令时候,Key 所在 SLOT 正在迁移数据”这个不太可能,因为即使不再迁移数据999线还是升高。
第三个onUncoveredSlot,当时并没有出现找不到Slot或者Slot未找到对应Redis节点。
而注意第二个:“ConnectionWatchdog 监听到 channelInactive,立即触发延迟重连,默认最多重连 5 次延迟提交机制”,这个是最有可能的,因为在我下线从节点的时候其实999线就已经升高了,而在我们恢复从节点后999线就恢复了。
所以事情是这样的。。。
- 从节点下线,业务机器和从节点之间的连接断开,大部分集群内部节点都forget了从节点,但是还有两个节点没有forget
- Lettuce触发集群拓扑刷新(我们配置的是60s刷新一次)
- 两个没有forget的节点仍然在集群中传播已经下线的节点信息,体现在cluster nodes命令中就是那些handshake的节点
- Lettuce获取的集群拓扑仍然包含handshake节点,依然会不断触发拓扑刷新 5.大量cluster nodes集中在某一个时间点,Redis短暂阻塞,导致业务查询出现999升高