zoukankan      html  css  js  c++  java
  • 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系列

    作者:三石君
    本文版权归作者所有,欢迎转载,但必须给出原文链接,并保留此段声明,否则保留追究法律责任的权利。
  • 相关阅读:
    C#-Linq-SelectMany
    C#-Linq-SelectMany
    DI是实现面向切面和面向抽象的前提
    java流程控制之Scanner(2)
    java流程控制之Scanner(1)
    java运算符之三目运算符
    java运算符之位运算
    java运算符之与或非
    java运算符之加减乘除
    java基础语法
  • 原文地址:https://www.cnblogs.com/zhroot/p/12356862.html
Copyright © 2011-2022 走看看