redis系列-14点的灵异事件

Posted 三石君

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了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
		#/bin/date >> $filename

	elif [ $currentHour -eq 06 ] && [ $currentMin -lt 05 ]; then
		ss -t -a >> $filename
		#/bin/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 这两个时间段的请求上没有明显的差异。基本上都是有以下请求构成

但是从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系列

以上是关于redis系列-14点的灵异事件的主要内容,如果未能解决你的问题,请参考以下文章

写代码遇到的灵异事件

圣安地列斯里不用下mode的各种隐藏城市,灵异事件,彩蛋什么的都有哪些

灵异事件

记一次2000端口灵异事件

出现灵异事件的嵌入式?——难查的数组越界神奇的volatile局部变量......

灵异事件之:Android Studio 3.4提示:Error running app: Default Activity Not Found