redis系列-14点的灵异事件

概述

项目组每天14点都会遭遇惊魂时刻。一条条告警短信把工程师从午后小憩中拉回现实。之后问题又神秘消失。是PM喊你上工了？还是服务器给你开玩笑？下面请看工程师如何一步一步揪出真凶，解决问题。

如果不想看故事，可以直接跳到最后事后烟章节下看和Redis相关部分。

起因

某天下午，后端组的监控系统发出告警，服务器响应时间变长，超过了阈值。过一会儿系统自动恢复了，告警解除。

第二天差不多的时间点，监控系统又发出了同样的告警，过几分钟后又恢复了。

我们决定排查这个问题。

背景

首先要介绍一下应用的架构，很简单的三层架构的web服务。

从外到内大概是这样的

• Load Balance:对外提供访问入口，对内实现负载均衡。
• Nginx:放在LB后面，实现流控等功能。
• App Service :逻辑服务，多机多进程。
• Storage:MySQL和Redis组成的存储层。

我们的服务部署在aws云上，架构里用到了很多aws的服务。
比如ELB,EC2,RDS等

表象

排查问题的第一步就是要收集信息。从监控和日志系统里提取大量的相关信息，然后再分析、解决问题。

我们收集到的信息大概是这样的

在每天14点的时候

• QPS突增
• P99指标升高
• App服务器集群CPU、内存都升高，tcp连接数暴涨，入网流量降低
• MySQL Write IOPS升高，写入延时升高，数据库连接数升高

几分钟后，这些指标都回归到正常水平。

排查

首先从代码入手，看看是不是有这个时间点的定时任务。结果发现并没有。

然后就是第一个怀疑对象MySQL

使用mysqlbinlog命令统计一下各个时间点的binlog数量

日志条数	UTC时间
624	6:00:37
396	6:00:38
933	6:00:51
834	6:00:52
402	6:01:24
2019	6:01:25
6030	6:01:26
7362	6:01:27
1479	6:01:28
1026	6:01:29
1320	6:01:30
954	6:01:31

我们又在第二天的这个时间点观察了一下现场

使用show processlist命令抓取一下当时MySQL连接的状态，结果发现来自App服务器的连接竟然都sleep了20秒左右，什么事儿都没做。

初步推论

根据以上的数据可以还原一下当时的场景

• App服务器socket数激增
• App服务器不再进行逻辑处理（这个待确认）
• App服务器不再进行任何数据库操作
• App服务器恢复读写数据库
• 积压了大量的网络请求 让游戏服务器cpu增加
• 大批量的写请求涌向数据库 造成数据库各项指标升高

那么问题来了

• 激增的socket来自哪里？
• 或者去连接了谁？
• App服务器为什么会长达20秒没有什么数据库操作？
• App服务器是真的hang住了？

带着疑问开始进一步排查

深入排查

先解决第一个问题 多出来的socket来自哪里？

App Service

在14点前 选一台App服务器，抓取它的tcp连接

#!/bin/bash
while [ true ]; do
    currentHour=$(date +%H)
    currentMin=$(date +%M)
    filename=$(date +%y%m%d%H%M%S).txt
    if [ $currentHour -eq 05 ] && [ $currentMin -gt 58 ];   then
        ss -t -a >> $filename
        #/binhttps://img.qb5200.com/download-x/date >> $filename

    elif [ $currentHour -eq 06 ] && [ $currentMin -lt 05 ]; then
        ss -t -a >> $filename
        #/binhttps://img.qb5200.com/download-x/date >> $filename
    elif [ $currentHour -ge 06 ] && [ $currentMin -gt 05 ]; then
        exit;
    fi 
    /bin/sleep 1
done

对大小差异比较大的文件进行比对，发现多出来的连接来自Nginx。

Nginx只是个代理，那就排查它的上游Load Balance。

Load Balance

Load Balance我们使用的是aws的经典产品ELB。

ELB的日志很大，主要是分析一下这段时间内有没有异常的流量。

经过对比分析 13:55-14:00 和14:00-14:05 这两个时间段的请求上没有明显的差异。基本上都是有以下请求构成

• https://xxxxxxx.xxxx.xxx:443/time
• https://xxxxx.xxxx.xxx:443/gateway/v1

但是从14:00:53开始，带gateway的请求大部分都返回504，带time的请求都正常返回。

504表示网关超时，就是App响应超时了。

根据这个信息有可以推断出一些情况

• App Service还在正常提供服务，否则time请求不会正常返回
• App Service所有写数据库的操作都处于等待的状态
• Nginx到App Service的连接得不到及时处理，所以连接很长时间没有断开，导致了Nginx和App Service的socket连接快速增长

根据以上，基本上可以排除是ELB,Nginx带来的问题。

那么问题就剩下一个，什么数据库长时间不可写呢? 而且每天都在固定时间。

MySQL

问题又回到了数据库上，首先想到的就是备份，但是我们的备份时间不在出问题的时间段。

我们使用的是aws的RDS服务，查阅了一下RDS关于备份的文档。

只有在数据库备份的时候才可能会出现写I/O挂起，导致数据库不可写。 而默认的备份时间窗口是这样的。

区域	时间窗口
美国西部（俄勒冈）区域	06:00–14:00 UTC
美国西部（加利福利亚北部）区域	06:00–14:00 UTC

这个开始的时间也刚好在我们出问题的时间，简直是太巧合了。

下一步就是要确认这个问题。

是在偷偷的帮我们做备份，还是实例所在的物理机上的其他实例干扰了我们？

在某个MySQL实例上建个新的数据库test，创建一张新表test。

CREATE TABLE `test` (
    `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
    `curdate` varchar(100) NOT NULL,
    PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8;

每秒钟往这张表里写条数据，数据的内容是当前时间，这样就能看出来在哪个时间段数据库不可写了。

同时每秒钟读取这张表的最大值，记录下结果和当前时间，这样就能看出来哪个时间段数据库不可读。

测试的脚本如下

#!/bin/bash
host=xxxx.xxx.xxx
port=3306
user=xxxxx
password=xxxxx

mysql="mysql -u$user -p$password -h$host -P$port --default-character-set=utf8 -A -N"

fetchsql="show processlist;"
selectsql="select max(id),now(3) from test.test;"
insertsql="insert into test.test(curdate) value(now(3));"

function run(){
    filename_prefix=$1
    mysqlcmd="$($mysql -e "$fetchsql")"
    echo $mysqlcmd >> $filename_prefix.procs.txt
    mysqlcmd="$($mysql -e "$selectsql")"
    echo $mysqlcmd >> $filename_prefix.select.txt   
    mysqlcmd="$($mysql -e "$insertsql" )"   
}
while [ true ]; do
    currentHour=$(date +%H)
    currentMin=$(date +%M)
    filename_prefix=./checksql/$(date +%y%m%d%H%M%S)
    $(run $filename_prefix)
    if [ $currentHour -eq 05 ] && [ $currentMin -gt 59 ];   then
        $(run $filename_prefix);

    elif [ $currentHour -eq 06 ] && [ $currentMin -lt 02 ]; then
        $(run $filename_prefix);

    elif [ $currentHour -ge 06 ] && [ $currentMin -gt 02 ]; then
        exit;
    fi

    /bin/sleep 1

done

这个脚本同时还每秒钟扫描一次MySQL各个客户端的工作状态。

最后得到的结论是，出现问题的时间点，数据库可读也可写。

问题好像陷入了困境。怀疑的点被一一证明没有问题。线索也断了。只能再回到起点了，继续从代码下手，看看哪里会造成单点，哪里出现了问题会让所有的游戏服务器集体卡住，或者是让数据库操作卡住。

Redis

终于排查到了罪魁祸首主角。

最可疑的有两个点

• 数据库分片的方案依赖Redis。Redis里存储了每个用户的数据库分片id，用来查找其数据所在的位置。

• 用户的设备和逻辑id的映射关系，也存储在Redis里。几乎每个API请求都要查找这个映射关系。

以上两点几乎是一个API请求的开始，如果这两点出现了问题，后续的操作都会被卡住。

经过和ops确认，这两个Redis的备份时间窗口确实在6:00-7:00utc。而且备份都是在从库上进行的，我们程序里的读操作也是在从库上进行的。

通过Redis的info命令，参考Redis最近一次的备份时间，时间点也刚好都在北京时间14:01左右。

进一步确认嫌疑

把两个Redis的备份时间做出更改。Redis1更换为3:00-4:00utc，Redis2更换为7:00-8:00utc。

北京时间 11:00左右 redis1正常备份。问题没有复现。

北京时间 14:00左右 问题没有复现。

北京时间 15:00左右 redis2正常备份。问题复现。

事后查看了一下redis1和redis2的数据量，redis2是redis1的5倍左右。
redis1占用内存1.3G左右，redis2占用内存6.0G左右。redis1的备份过程几乎在瞬间完成，对App的影响不明显。

结论

问题出现的大致过程是这样的

• redis2在北京时间的14点左右进行了从库备份。
• 备份期间导致了整个reids从库的读取操作被阻塞住。
• 进一步导致了用户的api请求被阻塞住。
• 这期间没有进行任何数据库的操作。
• 被逐渐积累的api请求，在备份完成的一小段时间内，给Nginx，App Service，Redis，RDS都带来了不小的冲击
• 所以出现了前文中描述的现象。

事后烟

其实问题的根源还在Redis的备份上，我们就来聊一下Redis的备份。

Redis的持久化可以分为两种方案；一种是全量方式RDB，一种是增量方式AOF。

详情可以参考官方中文翻译。

RDB

把内存中的全部数据按格式写入备份文件，这就是全量备份。

它又分为两种不同的形式。涉及到的Redis命令是SAVE/BGSAVE。

SAVE

总所周知，Redis服务都单线程的。SAVE和其他常见的命令一样，也是运行在主进程里的。可想而知，如果SAVE的动作很慢，其他命令都得排队等着它结束。

BGSAVE

BGSAVE命令也可以触发全量备份，但是Redis会为它fork出来一个子进程，BGSAVE命令运行在子进程里，它不会影响到Redis的主进程执行其他指令。它唯一的影响可能就是会在操作系统层面上和Redis主进程竞争资源(cpu, ram等)。

AOF

增量的备份方式有点像MySQL的binlog机制。它把
会改变数据的命令都追加写入的备份文件里。

这种方式是redis服务的行为，不对外提供命令

对比

两种方式可有优缺点。

• RDB文件较小，自定义格式有优势

• AOF文件较大，虽然Redis会合并掉一些指令，但是流水账还是会很大

• RDB备份时间长，无法做到细粒度的备份

• AOF每条指令都备份，可以做到细粒度

• 二者可以结合使用

Amazon ElastiCache for Redis

我们使用的是aws的托管服务，他们是怎么做备份的呢？

详情可以参考官方文档

Redis 2.8.22以前

使用BGSAVE命令，如果预留内存不足，可能会导致备份失败。

Redis 2.8.22及以后

如果内存不足，使用SAVE命令。

如果内存充足，使用BGSAVE命令。

大概要预留多少内存呢？aws官方推荐25%的内存。

很显然我们的实例的预留内存是不够这个数的，所以导致了问题的出现。

我觉得aws可以把备份做的更好。

---

更多redis系列