作者：三石君
笔者所在的公司有一款大DAU(日活)的休闲游戏。这款游戏的后端架构很简单，可以简单理解为通讯-逻辑-存储三层结构。其中存储层大量使用了Redis和MySQL。
随着存量用户的增加，Redis就隔三差五的出现问题。所以笔者打算把遇到的一系列问题以及在项目里的实践都整理记录下来。
项目组每天14点都会遭遇惊魂时刻。一条条告警短信把工程师从午后小憩中拉回现实，之后问题又神秘消失。
是PM喊你上工了?还是服务器给你开玩笑?下面请看工程师如何一步一步揪出真凶，解决问题。
1、起因
某天下午，后端组的监控系统发出告警，服务器响应时间变长，超过了阈值。过一会儿系统自动恢复了，告警解除。
第二天差不多的时间点，监控系统又发出了同样的告警，过几分钟后又恢复了。于是我们决定排查这个问题。
2、背景
首先要介绍一下应用的架构，是很简单的三层架构的Web服务，从外到内大概是这样的：
LoadBalance：对外提供访问入口，对内实现负载均衡。Nginx：放在LB后面，实现流控等功能。AppService：逻辑服务，多机多进程。Storage：MySQL和Redis组成的存储层。我们的服务部署在AWS云上，架构里用到了很多AWS的服务，比如ELB，EC2，RDS等。
3、表象
排查问题的第一步就是要收集信息。从监控和日志系统里提取大量的相关信息，然后再分析、解决问题。
我们收集到的信息大概是这样的，在每天14点的时候：
QPS突增。P99指标升高。App服务器集群CPU、内存都升高，TCP连接数暴涨，入网流量降低。MySQLWriteIOPS升高，写入延时升高，数据库连接数升高。几分钟后，这些指标都回归到正常水平。
4、排查
首先从代码入手，看看是不是有这个时间点的定时任务。结果发现并没有。然后就是第一个怀疑对象MySQL。
使用mysqlbinlog命令统计一下各个时间点的binlog数量：
我们又在第二天的这个时间点观察了一下现场，使用showprocesslist命令抓取一下当时MySQL连接的状态，结果发现来自App服务器的连接竟然都sleep了20秒左右，什么事儿都没做。
初步推论
根据以上的数据可以还原一下当时的场景：
App服务器Socket数激增。App服务器不再进行逻辑处理(这个待确认)。App服务器不再进行任何数据库操作。App服务器恢复读写数据库。积压了大量的网络请求让游戏服务器CPU增加。大批量的写请求涌向数据库造成数据库各项指标升高。那么问题来了：
激增的Socket来自哪里?或者去连接了谁?App服务器为什么会长达20秒没有什么数据库操作?App服务器是真的hang住了?带着疑问开始进一步排查。
5、深入排查
先解决第一个问题：多出来的Socket来自哪里?
AppService
在14点前，选一台App服务器，抓取它的TCP连接：
#!/bin/bashwhile[true];docurrentHour=(date+%H)currentMin=(date+%M)filename=(date+%y%m%d%H%M%S).txtif[currentHour-eq05][currentMin-gt58];thenss-t-afilename#/bin/datefilenameelif[currentHour-eq06][currentMin-lt05];thenss-t-afilename#/bin/datefilenameelif[currentHour-ge06][currentMin-gt05];thenexit;fi/bin/sleep1done
对大小差异比较大的文件进行比对，发现多出来的连接来自Nginx。Nginx只是个代理，那就排查它的上游LoadBalance。
LoadBalance
LoadBalance我们使用的是AWS的经典产品ELB。ELB的日志很大，主要是分析一下这段时间内有没有异常的流量。
经过对比分析13:55-14:00和14:00-14:05这两个时间段的请求上没有明显的差异。
但是从14:00:53开始，带gateway的请求大部分都返回，带time的请求都正常返回。表示网关超时，就是App响应超时了。
根据这个信息又可以推断出一些情况：
AppService还在正常提供服务，否则time请求不会正常返回。AppService所有写数据库的操作都处于等待的状态。Nginx到AppService的连接得不到及时处理，所以连接很长时间没有断开，导致了Nginx和AppService的Socket连接快速增长。根据以上，基本上可以排除是ELB，Nginx带来的问题。那么问题就剩下一个，什么数据库长时间不可写呢?而且每天都在固定时间。
MySQL
问题又回到了数据库上，首先想到的就是备份，但是我们的备份时间不在出问题的时间段。
我们使用的是AWS的RDS服务，查阅了一下RDS关于备份的文档。只有在数据库备份的时候才可能会出现写I/O挂起，导致数据库不可写。
而默认的备份时间窗口是这样的：
这个开始的时间也刚好在我们出问题的时间，简直是太巧合了。
下一步就是要确认这个问题。是在偷偷的帮我们做备份，还是实例所在的物理机上的其他实例干扰了我们?
在某个MySQL实例上建个新的数据库test，创建一张新表test：
CREATETABLE`test`(`id`int(10)unsignedNOTNULLAUTO_INCREMENT,`curdate`varchar()NOTNULL,PRIMARYKEY(`id`))ENGINE=InnoDBAUTO_INCREMENT=2DEFAULTCHARSET=utf8;
每秒钟往这张表里写条数据，数据的内容是当前时间，这样就能看出来在哪个时间段数据库不可写了。
同时每秒钟读取这张表的最大值，记录下结果和当前时间，这样就能看出来哪个时间段数据库不可读。
测试的脚本如下：
#!/bin/bashhost=xxxx.xxx.xxxport=user=xxxxxpassword=xxxxxmysql=mysql-uuser-ppassword-hhost-Pport--default-character-set=utf8-A-Nfetchsql=showprocesslist;selectsql=selectmax(id),now(3)fromtest.test;insertsql=insertintotest.test(curdate)value(now(3));functionrun(){filename_prefix=1mysqlcmd=(mysql-efetchsql)echomysqlcmdfilename_prefix.procs.txtmysqlcmd=(mysql-eselectsql)echomysqlcmdfilename_prefix.select.txtmysqlcmd=(mysql-einsertsql)}while[true];docurrentHour=(date+%H)currentMin=(date+%M)filename_prefix=./checksql/(date+%y%m%d%H%M%S)(runfilename_prefix)if[currentHour-eq05][currentMin-gt59];then(runfilename_prefix);elif[currentHour-eq06][currentMin-lt02];then(runfilename_prefix);elif[currentHour-ge06][currentMin-gt02];thenexit;fi/bin/sleep1done
这个脚本同时还每秒钟扫描一次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的影响不明显。
6、结论
问题出现的大致过程是这样的：
Redis2在北京时间的14点左右进行了从库备份。备份期间导致了整个Reids从库的读取操作被阻塞住。进一步导致了用户的API请求被阻塞住。这期间没有进行任何数据库的操作。被逐渐积累的API请求，在备份完成的一小段时间内，给Nginx，AppService，Redis，RDS都带来了不小的冲击。所以出现了前文中描述的现象。7、事后烟
其实问题的根源还在Redis的备份上，我们就来聊一下Redis的备份。
Redis的持久化可以分为两种方案：
全量方式RDB增量方式AOFRDB
把内存中的全部数据按格式写入备份文件，这就是全量备份。它又分为两种不同的形式。
涉及到的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每条指令都备份，可以做到细粒度。二者可以结合使用。AmazonElastiCacheforRedis
我们使用的是AWS的托管服务，他们是怎么做备份的呢?
Redis2.8.22以前：使用BGSAVE命令，如果预留内存不足，可能会导致备份失败。
Redis2.8.22及以后：如果内存不足，使用SAVE命令。如果内存充足，使用BGSAVE命令。
大概要预留多少内存呢?AWS官方推荐25%的内存。很显然我们的实例的预留内存是不够这个数的，所以导致了问题的出现。我觉得AWS可以把备份做的更好。