29-案例篇：Redis响应严重延迟，如何解决？

MySQL的MyISAM引擎，主要依赖系统缓存加速磁盘I/O的访问
可如果系统中还有其他应用同时运行，MyISAM引擎很难充分利用系统缓存
缓存可能会被其他应用程序占用，甚至被清理掉

所以并不建议，把应用程序的性能优化完全建立在系统缓存上
最好能在应用程序的内部分配内存，构建完全自主控制的缓存
或者使用第三方的缓存应用，比如Memcached、Redis等

Redis是最常用的键值存储系统之一，常用作数据库、高速缓存和消息队列代理等
Redis基于内存来存储数据
不过，为了保证在服务器异常时数据不丢失，很多情况下，要为它配置持久化
而这就可能会引发磁盘I/O的性能问题

案例

服务器配置

# 服务端（192.168.1.6）
# 机器配置：2cpu，4GB内存
# 预先安装docker、sysstat、git、make包

# 客户端（192.168.1.5）

# 案例说明
案例由Python应用、Redis两部分组成
Python应用是一个基于Flask的应用，它会利用Redis，来管理应用程序的缓存
并对外提供三个HTTP接口
1. /：返回hello redis
2. /init/：插入指定数量的缓存数据，如果不指定数量，默认的是5000条
           缓存的键格式为uuid
           缓存的值为good、bad或normal三者之一
3. /get_cache/<type_name>：查询指定值的缓存数据，并返回处理时间
           其中，type_name参数只支持good,bad和normal（也就是找出具有相同value的key列表）

在服务端，执行命令，运行本次案例需要分析的应用

#
[root@local_sa_192-168-1-6 ~]# docker run --name=redis -itd -p 10000:80 feisky/redis-server
2d1811589334f0f5615b1b85936ddbc4ee565b85d73c6bc887c4f5cadf9f195f

#
[root@local_sa_192-168-1-6 ~]# docker run --name=app --network=container:redis -itd feisky/redis-app

#
[root@local_sa_192-168-1-6 ~]# docker ps
CONTAINER ID   IMAGE                 COMMAND                  CREATED         STATUS          PORTS                                               NAMES
fb2709a1ba1e   feisky/redis-app      "python /app.py"         2 minutes ago   Up 15 seconds                                                       app
2d1811589334   feisky/redis-server   "docker-entrypoint.s…"   4 minutes ago   Up 4 minutes    6379/tcp, 0.0.0.0:10000->80/tcp, :::10000->80/tcp   redis

在客户端，使用curl工具测试

# 看到hello redis的输出，说明应用正常启动
[root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/
hello redis

# 调用应用的/init接口，初始化Redis缓存，并且插入5000条缓存信息
# 案例插入5000条数据，在实践时可以根据磁盘的类型适当调整
[root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/init/5000

# 访问应用的缓存查询接口
[root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/get_cache
{"count":1677,"data":["d97662fa-06ac-11e9-92c7-0242ac110002",...],"elapsed_seconds":10.5}
##
这个接口调用居然要花10秒！这么长的响应时间，显然不能满足实际的应用需求

# 为了避免分析过程中客户端的请求结束
[root@local_deploy_192-168-1-5 ~]# while true;do curl http://192.168.1.6:10000/get_cache; done

在服务端，执行top命令

[root@local_sa_192-168-1-6 ~]# top
top - 12:46:18 up 11 days, 8:49, 1 user, load average: 1.36, 1.36, 1.04
Tasks: 137 total, 1 running, 79 sleeping, 0 stopped, 0 zombie
%Cpu0 : 6.0 us, 2.7 sy, 0.0 ni, 5.7 id, 84.7 wa, 0.0 hi, 1.0 si, 0.0 st
%Cpu1 : 1.0 us, 3.0 sy, 0.0 ni, 94.7 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
KiB Mem : 8169300 total, 7342244 free, 432912 used, 394144 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7478748 avail Mem

PID   USER      PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
9181  root      20 0 193004 27304 8716 S 8.6 0.3 0:07.15 python
24428 systemd+  20 0 28352 9760 1860 D 5.0 0.1 0:04.34 redis-server

##
观察top的输出可以发现，CPU0的iowait比较高，已经达到了84%
而各个进程的CPU使用率都不太高
最高的python和redis-server，也分别只有8%和5%
再看内存，显然内存也没啥问题
##
综合top的信息，最有嫌疑的就是iowait

在服务端，执行iostat命令

[root@local_sa_192-168-1-6 ~]# iostat -d -x 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月22日 	_x86_64_	(2 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.04     0.42    2.11    1.12  1808.76   159.83  1215.80     0.04   11.40    8.79   16.32   8.33   2.70
scd0              0.00     0.00    0.00    0.00     0.00     0.00     0.33     0.00    0.11    0.11    0.00   0.56   0.00
dm-0              0.00     0.00    0.85    1.19  1808.70   160.14  1925.44     0.07   33.17   20.18   42.44   8.44   1.73
dm-1              0.00     0.00    0.00    0.00     0.01     0.00    51.80     0.00   32.79   32.79    0.00  19.53   0.00
##
观察iostat的输出发现，磁盘sda每秒的写数据（wkB/s）为159KB
I/O 使用率（%util）是0
虽然有些I/O操作，但并没导致磁盘的I/O瓶颈

在服务端，执行pidstat命令

[root@local_sa_192-168-1-6 ~]# pidstat -d 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月22日 	_x86_64_	(2 CPU)
14时47分07秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时47分08秒   100     24428      0.00    178.22      0.00  redis-server

14时47分08秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时47分09秒   100     24428      0.00    180.00      0.00  redis-server

14时47分09秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14时47分10秒   100     24428      0.00    172.00      0.00  redis-server

平均时间:   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
平均时间:   100     24428      0.00    186.59      0.00  redis-server
##
从pidstat的输出看到，I/O最多的进程是PID为24428的redis-server
并且它也刚好是在写磁盘，这说明确实是redis-server在进行磁盘写

在服务端，执行strace和lsof命令

# -f 表示跟踪子进程和子线程
# -T 表示显示系统调用的时长
# -tt 表示显示跟踪时间
[root@local_sa_192-168-1-6 ~]#  strace -f -T -tt -p 24428
[pid 24428] 14:47:35.448140 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 52, NULL, 8) = 1 <0.000142>
[pid 24428] 14:47:35.448421 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:6c9c7502-"..., 16384) = 61 <0.000072>
[pid 24428] 14:47:35.449600 read(3, 0x7fffabf2d427, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000070>
[pid 24428] 14:47:35.449812 write(8, "$4\r\ngood\r\n", 10) = 10 <0.000089>
......
[pid 24428] 14:47:35.450204 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 49, NULL, 8) = 1 <0.000164>
[pid 24428] 14:47:35.450512 read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n6c9"..., 16384) = 67 <0.000083>
[pid 24428] 14:47:35.451660 read(3, 0x7fffabf2d427, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000066>
[pid 24428] 14:47:35.451839 write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n6c9"..., 67) = 67 <0.000073>
[pid 24428] 14:47:35.451839 fdatasync(7) = 0 <0.005415>
......
##
从系统调用来看，epoll_pwait、read、write、fdatasync这些系统调用都比较频繁
那么，刚才观察到的写磁盘，应该就是write或者fdatasync导致的了
## lsof
[root@local_sa_192-168-1-6 ~]# lsof -p 24428
......
redis-ser 24428      100    3r     FIFO   0,13      0t0    124969 pipe
redis-ser 24428      100    4w     FIFO   0,13      0t0    124969 pipe
redis-ser 24428      100    5u  a_inode   0,14        0      8460 [eventpoll]
redis-ser 24428      100    6u     sock    0,8      0t0    124970 protocol: TCP
redis-ser 24428      100    7w      REG  253,0   948344 176182428 /data/appendonly.aof
redis-ser 24428      100    8u     sock    0,8      0t0    126166 protocol: TCP
##
描述符编号为3的是一个pipe管道
5号是eventpoll
7号是一个普通文件
8号是一个TCP socket
##
结合磁盘写的现象，只有7号普通文件才会产生磁盘写
而它操作的文件路径是/data/appendonly.aof
相应的系统调用包括write和fdatasync

## redis基础知识
Redis持久化配置中有appendonly和appendfsync选项
很可能是因为它们的配置不合理，导致磁盘写比较多

在服务端，查看redis配置

[root@local_sa_192-168-1-6 ~]# docker exec -it redis redis-cli config get 'append*'
1) "appendfsync"
2) "always"
3) "appendonly"
4) "yes"
##
appendfsync配置的是always
appendonly配置的是yes
########
# Redis提供了两种数据持久化的方式，分别是快照和追加文件
1. 快照方式，会按照指定的时间间隔，生成数据的快照，并且保存到磁盘文件中。
为了避免阻塞主进程，Redis还会fork出一个子进程，来负责快照的保存。
这种方式的性能好，无论是备份还是恢复，都比追加文件好很多
不过，它的缺点也很明显
在数据量大时，fork子进程需要用到比较大的内存，保存数据也很耗时
所以，需要设置一个比较长的时间间隔来应对，比如至少5分钟
这样，如果发生故障，丢失的就是几分钟的数据

2. 追加文件，则是用在文件末尾追加记录的方式，对Redis写入的数据，依次进行持久化，所以它的持久化也更安全
此外，它还提供了一个用appendfsync选项设置fsync的策略，确保写入的数据都落到磁盘中
具体选项包括always、everysec、no等
always表示，每个操作都会执行一次fsync，是最为安全的方式
everysec表示，每秒钟调用一次fsync，这样可以保证即使是最坏情况下，也只丢失1秒的数据
no表示，交给操作系统来处理
########
案例中appendfsync配置的是always，意味着每次写数据时，都会调用一次fsync，从而造成比较大的磁盘I/O压力

在服务端，执行strace命令，查看系统调用的执行情况

[root@local_sa_192-168-1-6 ~]# strace -f -p 24428 -T -tt -e fdatasync
[pid 24428] 14:50:09.346201 fdatasync(7) = 0 <0.022991>
[pid 24428] 14:50:09.373546 fdatasync(7) = 0 <0.020661>
[pid 24428] 14:50:09.396243 fdatasync(7) = 0 <0.015645>
[pid 24428] 14:50:09.416852 fdatasync(7) = 0 <0.019023>
[pid 24428] 14:50:09.441939 fdatasync(7) = 0 <0.011531>
[pid 24428] 14:50:09.455621 fdatasync(7) = 0 <0.021865>
[pid 24428] 14:50:09.479623 fdatasync(7) = 0 <0.022748>
[pid 24428] 14:50:09.506912 fdatasync(7) = 0 <0.013260>
[pid 24428] 14:50:09.523493 fdatasync(7) = 0 <0.020520>
[pid 24428] 14:50:09.548724 fdatasync(7) = 0 <0.020336>
[pid 24428] 14:50:09.571242 fdatasync(7) = 0 <0.022781>
[pid 24428] 14:50:09.596195 fdatasync(7) = 0 <0.015596>
[pid 24428] 14:50:09.616554 fdatasync(7) = 0 <0.027589>
[pid 24428] 14:50:09.648494 fdatasync(7) = 0 <0.020671>
[pid 24428] 14:50:09.671379 fdatasync(7) = 0 <0.022808>
[pid 24428] 14:50:09.696326 fdatasync(7) = 0 <0.015559>
[pid 24428] 14:50:09.715756 fdatasync(7) = 0 <0.019982>
[pid 24428] 14:50:09.744767 fdatasync(7) = 0 <0.082734>
[pid 24428] 14:50:09.830990 fdatasync(7) = 0 <0.023048>
[pid 24428] 14:50:09.857060 fdatasync(7) = 0 <0.013441>
[pid 24428] 14:50:09.872742 fdatasync(7) = 0 <0.014465>
##
调用非常频繁
##
找出了Redis正在进行写入的文件，也知道了产生大量I/O的原因
##
为什么查询时会有磁盘写呢？按理来说不应该只有数据的读取吗？
[root@local_sa_192-168-1-6 ~]# strace -f -T -tt -p 24428
read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53522908-"..., 16384)
write(8, "$4\r\ngood\r\n", 10)
read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 16384)
write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 67)
write(8, ":1\r\n", 4)
##
根据lsof的分析，文件描述符编号为7的是一个普通文件/data/appendonly.aof
编号为8的是TCP socket
观察上面的内容，8号对应的TCP读写，是一个标准的“请求-响应”格式，即
从socket读取GET uuid:53522908-… 后，响应good
再从socket读取SADD good 535… 后，响应1
##
对Redis来说，SADD是一个写操作，所以Redis还会把它保存到用于持久化的appendonly.aof文件中
观察更多的strace结果发现，每当GET返回good时，随后都会有一个SADD操作
这也就导致了，明明是查询接口，Redis却有大量的磁盘写
到这里就找出了Redis写磁盘的原因
###
可以给lsof命令加上-i选项，找出TCP socket对应的TCP连接信息
不过，由于Redis和Python应用都在容器中运行
需要进入容器的网络命名空间内部，才能看到完整的TCP连接
nsenter工具，可以进入容器命名空间

在服务端，运行nsenter工具

# 如果系统没有安装，请运行下面命令安装nsenter
[root@local_sa_192-168-1-6 ~]# docker run --rm -v /usr/local/bin:/target jpetazzo/nsenter

# 由于这两个容器共享同一个网络命名空间，所以只需要进入app的网络命名空间即可
[root@local_sa_192-168-1-6 ~]# PID=$(docker inspect --format {{.State.Pid}} app)

# -i 表示显示网络套接字信息
[root@local_sa_192-168-1-6 ~]# nsenter --target $PID --net -- lsof -i
COMMAND     PID     USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
lsof: no pwd entry for UID 100
redis-ser 24428      100    6u  IPv4 124970      0t0  TCP localhost:6379 (LISTEN)
lsof: no pwd entry for UID 100
redis-ser 24428      100    8u  IPv4 126166      0t0  TCP localhost:6379->localhost:35994 (ESTABLISHED)
python    24623     root    3u  IPv4 125178      0t0  TCP *:http (LISTEN)
python    24623     root    4u  IPv4 129547      0t0  TCP local_sa_192-168-1-6:http->192.168.1.5:42294 (ESTABLISHED)
python    24623     root    5u  IPv4 126165      0t0  TCP localhost:35994->localhost:6379 (ESTABLISHED)
##
这次可以看到，redis-server的8号文件描述符，对应TCP连接 localhost:6379->localhost:35994
其中，localhost:6379是redis-server自己的监听端口，自然localhost:35994就是redis的客户端
再观察最后一行，localhost:35994对应的，正是Python应用程序（进程号为24623）

2个问题

第一个问题，Redis配置的appendfsync是always，这就导致Redis每次的写操作，都会触发fdatasync系统调用
今天的案例，没必要用这么高频的同步写，使用默认的1s时间间隔，就足够了

第二个问题，Python应用在查询接口中会调用Redis的SADD命令，这很可能是不合理使用缓存导致的

## 解决办法
# 1. 对于第一个配置问题，可以执行下面的命令把appendfsync改成everysec
[root@local_sa_192-168-1-6 ~]# docker exec -it redis redis-cli config set appendfsync everysec
##
改完后会发现，现在的请求时间已经缩短到了0.9秒

# 2. 第二个问题，就要查看应用的源码了
[root@local_sa_192-168-1-6 ~]# docker cp app:/app.py .

[root@local_sa_192-168-1-6 ~]# cat app.py 
#!/usr/bin/env python
# -*- coding: UTF-8 -*-
from functools import wraps
from time import time
import json
import random
import uuid
import redis
from flask import Flask, jsonify

app = Flask(__name__)
redis_client = redis.StrictRedis(
    host="127.0.0.1", charset="utf-8", port=6379, db=0, decode_responses=True)


def timing(f):
    '''wrapper for elapsed_seconds'''
    @wraps(f)
    def wrapper(*args, **kwargs):
        start = time()
        result = f(*args, **kwargs)
        end = time()
        data = json.loads(result.get_data())
        data["elapsed_seconds"] = end-start
        return jsonify(data)
    return wrapper


@app.route('/')
def hello_world():
    '''handler for /'''
    return 'hello redis\n'


@app.route('/get_cache', defaults={'type_name': 'good'})
@app.route("/get_cache/<type_name>")
@timing
def get_cache(type_name):
    '''handler for /get_cache'''
    for key in redis_client.scan_iter("uuid:*"):
        value = redis_client.get(key)
        if value == type_name:
            redis_client.sadd(type_name, key[5:])
    data = list(redis_client.smembers(type_name))
    redis_client.delete(type_name)
    return jsonify({"type": type_name, 'count': len(data), 'data': data})


@app.route('/get_cache_data', defaults={'type_name': 'good'})
@app.route("/get_cache_data/<type_name>")
@timing
def get_cache_data(type_name):
    '''handler for /get_cache_data'''
    keys = [key for key in redis_client.scan_iter("uuid:*")]
    values = redis_client.mget(keys)
    matched_keys = set([keys[idx][5:] for idx, value in enumerate(values) if value == type_name ])
    return jsonify({"type": type_name, 'count': len(matched_keys), 'data': list(matched_keys)})


@app.route('/init', defaults={'num':5000})
@app.route('/init/<num>')
@timing
def initialize(num):
    '''handler for /init'''
    redis_client.flushall()
    types = ('good', 'bad', 'normal')
    sample_size = int(num)
    random_pool = random.sample(range(0, sample_size), sample_size)

    for i in range(sample_size):
        key = uuid.uuid1()
        redis_client.set('uuid:{}'.format(key), types[(random_pool[i]+i) % 3])

    return jsonify({"keys_initialized": sample_size})


if __name__ == '__main__':
    app.run(host='0.0.0.0', port=80)
    
##
果然，Python应用把Redis当成临时空间，用来存储查询过程中找到的数据
这些数据放内存中就可以了，完全没必要再通过网络调用存储到Redis中
##
这个接口把查询过程中产生的数据直接存储在内存了
http://192.168.1.6:10000/get_cache_data

小结

Redis缓存的案例
先用top、iostat ，分析了系统的CPU 、内存和磁盘使用情况
不过却发现，系统资源并没有出现瓶颈

这个时候想要进一步分析的话，该从哪个方向着手呢？
通过今天的案例发现，为了进一步分析，就需要对系统和应用程序的工作原理有一定的了解

比如，今天的案例中，虽然磁盘I/O并没有出现瓶颈，但从Redis的原理来说，查询缓存时不应该出现大量的磁盘I/O写操作

顺着这个思路，继续借助pidstat、strace、lsof、nsenter等一系列的工具
找出了两个潜在问题
一个是Redis的不合理配置
另一个是Python应用对Redis的滥用
找到瓶颈后，相应的优化工作自然就比较轻松了

posted @ 2021-12-22 17:10 李成果阅读(283) 评论(0) 编辑收藏举报

会员力量，点亮园子希望

刷新页面返回顶部

Alnk

邮箱:1029612787@qq.com

29-案例篇：Redis响应严重延迟，如何解决？

案例

小结

公告