Redis响应延迟案例

一. 上节回顾

文件系统和磁盘的理论知识

二. Redis响应延迟案例

1. 什么是Redis

Redis是一个高性能的key-value数据库，和memcached类似，它支持存储的value类型相对更多，包括string(字符串)，list(列表)，set(集合)，zset(sorted set，有序集合)和hash(哈希类型)，这些数据类型都支持push/pop，add/remove以及取交集、并集和差集及更丰富的操作，而且这些操作都是原子性的，在此基础上，Redis支持各种不同方式的排序，与memcached一样，为了保证效率，数据都缓存在内存中，区别是Redis会周期性的把更新的数据写入磁盘或把修改操作写入追加的记录文件，并且在此基础上实现了主从(master-slave)同步

2. 案例背景

分析一个利用Redis作为缓存的案例，通过查询缓存的接口，但接口的响应时间比较长，不能满足性能的需求

该案例由Python + Redis两部分组成，Redis来管理应用程序的缓存，并对外提供三个HTTP接口

(1) /：返回pertest Redis

(2) /init/数量：插入指定数量的缓存数据，不指定数量，默认是5000条

(3) 缓存的键值对格式为UUID

(4) 缓存的值为good、bad、normal三者之一

(5) get_cache/<type_name>：查询指定值的缓存数据，并返回处理时间

3. 步骤

(1) 将项目包redis-slow.zip上传到服务器的/data目录下，使用unzip解压

(2) 查看Makefile中的操作步骤

(3) 使用docker build

注意：必须cd到/data/redis-slow下，才能build

docker build -t pertest/redis-app -f Dockerfile .       #用docker来build一个名称为pertest/redis-app的镜像，并且根据配置文件配置的信息，去下载镜像文件。这个是Redis的客户端
docker build -t pertest/redis-server -f Dockerfile.redis .      #这是Redis的服务端

build过程中遇到了一个RUN pip install flask时的报错：

网上找到的解决办法，只要在/etc/resolv.conf 下添加如下代码就行，原因是Docker没有使用正确的DNS服务器

nameserver 8.8.8.8

正确配置好，可以build成功

(4) 启动Redis server和客户端

docker run --name=redis -itd -p 9090:80 pertest/redis-server
docker run --name=app --network=container:redis -itd pertest/redis-app

(5) 插入并读取数据

curl http://192.168.0.110:9090/init/20000   #插入20000条数据
curl http://192.168.0.110:9090/get_cache    #读取数据

当我们发现有2万条数据的时候，读取一次差不多需要8s，数据越多，发现响应时间越大

(6) jmeter设置阶梯场景，并发请求这个查询接口

(7) 分析结果

使用top命令，输出可以看到，CPU的use%态占比并不高，1.5%。看占用最高的两个进程python和redis-server，分别是49.2%，33.2%，但是我们的响应时间有6s以上，TPS也比较低，这个时候，应该怎么定位问题？

综合以上的情况，我们看到iowait是2.9%左右，其他值也都比较低，我们可以看看 iostat -x 3 的输出

w/s差不多达到2M/s，%util达到90%以上，，说明I/O存在严重的瓶颈

 

这时候，我们从分析对象(Python + Redis)，系统原理，性能工具三个方向入手，来看它们的特性。本案例是从Redis缓存中查询数据，并且很慢，对查询来水，对应的I/O应该是磁盘的读操作，但是刚刚通过iostat命令看到的是写操作，这里的磁盘写就比较奇怪了，我们需要定位下是哪个进程在写磁盘

pidstat -d 3

从pidstat的输出，看到I/O最多的进程是PID为55275的redis-server，并且它刚好是在写磁盘，这说明确实是redis-server在进程写磁盘

只找到读写磁盘的进程还不够，还要用strace + lsof组合

strace -f -T -tt -p 7688

-f：表示显示子进程和子线程

-T：表示显示系统调用的时长

-tt：表示显示跟踪时间

[pid 7688] 21:15:25.909333 read(8, "*2 $3 GET $41 uuid:acbbc42c-"..., 16384) = 61 <0.000116>
[pid 7688] 21:15:25.909775 read(3, 0x7ffdbcb7a667, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000125>
[pid 7688] 21:15:25.910167 write(8, "$4 good ", 10) = 10 <0.000160>
[pid 7688] 21:15:25.910595 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 77, NULL, 8) = 1 <0.000310>
[pid 7688] 21:15:25.911150 read(8, "*3 $4 SADD $4 good $36 acb"..., 16384) = 67 <0.000074>
[pid 7688] 21:15:25.911397 read(3, 0x7ffdbcb7a667, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000091>
[pid 7688] 21:15:25.911609 write(7, "*3 $4 SADD $4 good $36 acb"..., 67) = 67 <0.000103>
[pid 7688] 21:15:25.911993 fdatasync(7) = 0 <0.000850>

通过上面观察发现，上面这些是频率最高的，接着再运行lsof目录，找出系统调用的操作对象

lsof -p 7688

会发现描述符编号为3的是一个pipe管道，5号是eventpill，6号是TCP socket，17号/data/appendonly.aof是一个普通文件

结合磁盘写的现象，可以知道只有17号普通文件才会产生磁盘写，它操作的文件路径是：/data/appendpnly.aof

这个时候，就需要对Redis的原理或者配置比较熟悉了，才能想到问题。可以通过了解Redis的持久化配置知道，看到这个路径(/data/appendpnly.aof)及上面的(fdatasync(17) = 0 <0.000947>)的系统调用，会想到这对应着Redis持久化配置中的appendonly和appendsync选项，有可能是因为它们的配置不合理，导致磁盘写比较多

我们需要验证下这个猜测，通过Redis的命令行工具，查询这两个选项的配置

继续在终端运行下面的命令，查询appendonly和appendfsync选项

docker exec -it redis redis-cli config get 'append*'

从这个配置可以看到，"appendfsync"配置的是always，而"appendonly"配置是yes

Redis提供的两种数据持久化的方式：快照和追加文件

快照：会按照指定的时间间隔，生成数据的快照，并且保存到磁盘文件中，为了避免阻塞主进程，Redis会fork出一个子进程，来负责快照的保存，这种方式的性能比较好，无论是备份还是恢复，都比追加文件好很多

缺点：在数据量大时，fork子进程需要用到比较大的内存，保存数据也很耗时，所以需要一个比较长的时间间隔来对应，比如至少5分钟，这样如果发生故障，丢失的就是几分钟的数据

追加文件：是用在文件末尾追加记录的方式，对Redis写入的数据，依次进行持久化，所以它的持久化更安全，它提供了一个用"appendfsync"进行设置fsync的策略，来确保写入的数据都落在磁盘中，选择包括always，everysec，no等

　　always：每个操作都会执行一次fsync，是最安全的方式

　　everysec：每秒钟调用一次fsync，就算丢失，也只会丢失1秒的数据

　　no：交给操作系统来处理

在上面的配置中，1）"appendfsync"配置的是"always"，也就是每次写数据时，都会调用一次fsync，这样会造成比较大的磁盘IO压力，用strace命令，来观察这个系统调用的执行情况

strace -f -p 9022 -T -tt -e fdatasync    #这个pid之所以和上面的55275不一样，是因为redis客户端和服务器的容器被我停掉，再次启动了

从这里可以看到，每隔1ms左右，就会有一次fdatasync调用，并且每次调用本身也消耗6ms左右

不管哪种方式，都可以验证我们的猜想，Redis的配置存在不合理，到此为止，我们找到了Redis正在进行写入的文件，也知道了产生大量I/O的原因

为什么查询会有磁盘写？按照常规来说，不是应该只有数据的读取吗？

write(8, "$4
good
", 10) = 10 <0.000433>
read(8, "*3
$4
SADD
$4
good
$36
5e0"..., 16384) = 67 <0.000086>

继续输入如下命令：

lsof -p 7688

根据lsof的分析，文件描述符为7的是一个普通文件，编号为6的是TCP socket，从上面的内容中，6号和8号对应的是TCP的读写

write(8, "$4
good
", 10) = 10 <0.000433>

这是一个标准的"请求--响应"格式

read(8, "*2
$3
GET
$41
uuid:acbbc42c-"..., 16384) = 61 <0.000116>
read(3, 0x7ffdbcb7a667, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000125>
write(8, "$4
good
", 10) = 10 <0.000160>
read(8, "*3
$4
SADD
$4
good
$36
acb"..., 16384)
write(7, "*3
$4
SADD
$4
good
$36
acb"..., 67)

从socket读取GET uuid acbbc42c-后，响应了good；

再从socket读取SADD good后，响应了...

对Redis来说，SADD是一个写操作，所以Redis还会把它保存到持久化的appendonly.aof文件中，观察一段strace结果，会发现，每当get返回good时，随后都有一个sadd操作，也导致了虽然是查询接口，Redis却又大量的磁盘读写操作

已经找出了Redis写磁盘的原因，可以确认一下，8号的TCP socket对应的Redis客户端，是不是我们的案例应用？

PID=$(docker inspect --format {(.State.Pid}} app)    #获取到docker为APP应用的pid

nsenter --target $PID --net --lsof -i    # -i：表示显示网络套接字信息

=============================================