一、Redis Slowlog介绍

Redis slowlog是排查性能问题关键监控指标。它是记录Redis queries运行时间超时特定阀值的系统。
这类慢查询命令被保存到Redis服务器的一个定长队列，最多保存slowlog-max-len(默认128）个慢查询命令。
当慢查询命令达到128个时，新产生的慢查询被加入前，会从队列中删除最旧的慢查询命令。

1.1 Redis Slowlog的配置

redis slowlog通过2个参数配置管理，默认命令耗时超过10毫秒，就会被记录到慢查询日志队列中；队列默认保存最近产生的128个慢查询命令。
slowlog-log-slower-than: 慢查询阀值,单位微秒. 默认100000(10毫秒);
生产环境设置1ms,因为Redis是single thread,如果命令都是1ms以上,则实例的吞吐量只有1000QPS.
slowlog-max-len: 慢查询存储的最大个数,默认128;
生产设置设置大于1024,因为slowlog会省略过多的参数，慢查询不会占用过多的内存；
慢查询队列满后,淘汰最老的慢查询实体。

1.2 Redis Slowlog读取

redis-cli客户端通过slowlog get指令获取最新10条慢查询命令。
当然各语言的client也实现对应的接口。

示例：获取最近2个慢查询命令
127.0.0.1:6381> SLOWLOG get 2
1) 1) (integer) 62) (integer) 14587342633) (integer) 743724) 1) "hgetall"2) "max.dsp.blacklist"
2) 1) (integer) 52) (integer) 14587342583) (integer) 54110754) 1) "keys"2) "max.dsp.blacklist"
分析slowlog query：以第一个HGET命令为例分析，每个slowlog实体共4个字段：* 字段1：1个整数,表示这个slowlog出现的序号,server启动后递增, 当前为6.* 字段2：表示查询执行时的Unix时间戳.* 字段3：表示查询执行微妙数,当前是74372微妙,约74ms.* 字段4: 表示查询的命令和参数,如果参数很多或很大,只会显示部分并给数参数个数;当前命令是"hgetall"   "max.dsp.blacklist"

1.3 Redis Slowlog只计算命令的执行时间

如MySQL/MongoDB等常见数据库，慢查询的query_time都会包含命令所有耗时，包含锁等待这类时间；而Redis的慢查询query_time只记录自己“被cpu服务的时间”，不包含排队等待、IO等待（如AOF SYNC）这类时间。
理解这点非常重要

参考：The Redis Slow Log is a system to log queries that exceeded a
specified execution time. The execution time does not include I/O
operations like talking with the client, sending the reply and so forth,
but just the time needed to actually execute the command (this is the only
stage of command execution where the thread is blocked and can not serve
other requests in the meantime).

二、Redis Slowlog测试

设定请求的响应时间(R),服务时间(S), 排队延时（Q).
R = S + Q

我们回到Redis的Slowlog问题上，上节已说slowlog只计算Redis命令被服务的时间，并不包含命令的排队延迟时间。
2.1 现在做个测试：
1、redis实例port=6379,分别打开两个session. session-1模拟一个执行耗时6秒的大命令debug sleep 6；隔几秒后session-2执行一个简单的set a b的命令。
2、2个sessions的命令执行完成后，查看redis slowlog记录的命令耗时（slowlog-log-slower-than设置0）

session1:
rendeMacBook-Pro:~ rentom$ redis-cli
127.0.0.1:6379> debug sleep 6
OK
(6.00s)session2:
127.0.0.1:6379> set name tom
OK
(5.14s)
127.0.0.1:6379> slowlog get
1) 1) (integer) 152) (integer) 15389806143) (integer) 44) 1) "set"2) "name"3) "tom"5) "127.0.0.1:53738"6) ""
2) 1) (integer) 142) (integer) 15389806143) (integer) 60010614) 1) "debug"2) "sleep"3) "6"5) "127.0.0.1:53737"6) ""

2.2 测试结论
1、从redis响应时间监控(min列），可见set name tom命令耗时5.14s；
但从redis slowlog中查看set name tom命令耗时为4微秒，可见slowlog没有记录set命令排队延迟等待的时间。
2、因Redis是单线程模型，debug sleep阻塞了set命令，set命令的整体响应时间(R)是5.14S，而其服务时间(S)为4微秒，排队延迟(Q)约为5.14秒。

三、Redis Single-threads的问题

Redis Server是单线程的处理(bgsave或aof重写时会Fork子进程处理），同一时间只能处理一个命令，并且是同步完成的。
从上节的测试中可见，set命令服务时间只有4微秒，但被debug sleep 6命令阻塞后，响应时间变成5.14秒。
所以RD和DBA在设计keyspace和访问模式时，应尽量避免使用耗时较大的命令。
在理想状态下，Redis单实例能处理8~10w的QPS, 如果大量的redis命令大量耗时大于1ms, 其实QPS只能达到1000基于几百。
Redis出现耗时大的命令，导致其他所有请求被阻塞等待，redis处理能力急剧退化，易导致整个服务链雪崩。

转载：https://my.oschina.net/u/3023401/blog/2231347

Redis 性能问题排查：slowlog 和排队延时相关推荐

Redis——性能问题排查
对于开发者来说,Redis是个速度非常快的key-value内存数据库,并提供了方便的API接口.为了最好最优的使用Redis,需要理解哪些因素能影响到Redis性能,哪些数据指标能帮助我们避免性能陷 ...
Redis性能问题排查解决手册（值得收藏）
点击上方好好学java ,选择星标公众号重磅资讯.干货,第一时间送达今日推荐:今天给大家推荐 6 个 Spring Boot 项目,拿来就可以赚钱! 个人原创100W+访问量博客:点击前往, ...
Redis性能问题排查解决手册(七)
阅读目录: 性能相关的数据指标内存使用率used_memory 命令处理总数total_commands_processed 延迟时间内存碎片率回收key 总结性能相关的数据指标通过Red ...
Redis性能问题排查方法及优化
查看Redis各项指标首先要能够连接到Redis并获取性能相关的指标. 本文使用redis-cli客户端指令连接到Redis,使用info [section]命令获取相关指标. 不指定section ...
从几百个生产环境总结出的Redis性能问题排查解决手册（值得收藏）
点击上方蓝字,关注我们阅读目录: 性能相关的数据指标内存使用率used_memory 命令处理总数total_commands_processed 延迟时间内存碎片率回收key 总结性能相关 ...
记一次线上Redis高负载排查经历
作者:JingQ https://www.sevenyuan.cn/ 周一早上刚上班,突然大量用户反馈进入网页很慢,登录服务器一看,Redis调用时间严重超时,这样高速的缓存反而变成了短板,由于数据一 ...
Redis高负载排查记录
Redis简单运维学习周一早上刚上班,突然大量用户反馈进入网页很慢,登录服务器一看,Redis调用时间严重超时,这样高速的缓存反而变成了短板,由于数据一直没有返回,导致了请求响应变慢. 网页监控通 ...
Redis为什么变慢了？一文讲透如何排查Redis性能问题 | 万字长文
阅读本文大约需要 30 分钟. Redis 作为优秀的内存数据库,其拥有非常高的性能,单个实例的 OPS 能够达到 10W 左右.但也正因此如此,当我们在使用 Redis 时,如果发现操作延迟变大的情 ...
Redis为什么变慢了？一文详解Redis性能问题 | 万字长文
Redis 作为优秀的内存数据库,其拥有非常高的性能,单个实例的 OPS 能够达到 10W 左右.但也正因此如此,当我们在使用 Redis 时,如果发现操作延迟变大的情况,就会与我们的预期不符. 你也 ...

Redis 性能问题排查：slowlog 和排队延时