redis性能调优时，可能遇过类似的性能问题:”服务调用redis P99响应时间大于100ms，但在redis slowlog中却没有发现大于1ms的命令”；本文从解读redis slowlog和redis single-threaded排队延时两个方面,分析为何slowlog不完全可靠和耗时高的命令对redis性能影响。
目录：
redis slowlog参数设置
redis slowlog输出字段
redis slowlog耗时的实际含义
Queueing Delay
redis是single-threaded
单线程服务的throughput优化
redis slowlog参数设置
redis slowlog是记录redis命令运行时间大于指定阀值的系统；慢查询命令被保存到redis的一个定长FIFO队列，当队列装满后，新产生的慢查询命令被加入前，会从队列中删除最旧的慢查询命令。
redis slowlog通过2个参数设置：
slowlog-log-slower-than: 慢查询阀值（单位:微秒) 默认10000(10毫秒），即单个redis命令执行耗时达到10毫秒，就会记录到slowlog中。建议生产环境设置为1000(1毫秒)，因为redis是单线程服务，如果命令都是1ms以上,则redis每秒只能处理小于1000次请求(即1000QPS)，但业务使用redis往往单个实例达数万QPS.
slowlog-max-len: 慢查询存储的最大个数,默认128。
生产设置设置大于1024,因为slowlog会省略命令过长的内容，不会占用过多的内存；
慢查询队列满后,淘汰最老的慢查询实体。另外为方便分析性能问题，建议定期对redis slowlog进行转存，在新的文章
两个参数都可使用config set命令，进行动态修改，不用重启redis就能实时生效。
:6379> config set slowlog-log-slower-than 1000 阀值修改为1ms OK :6379> config set slowlog-max-len 1024 慢查询存储队列长度修改为1024 OK :6379> config get *slowlog* 获取修改后参数的值 1) "slowlog-log-slower-than" 2) "1000" 3) "slowlog-max-len" 4) "1024"
redis slowlog输出字段
redis-cli客户端通过slowlog get指令获取最新10条慢查询命令；当然各语言的client也实现对应的接口。(注:redis4.0的slowlog多出两个重要字段，执行client ip:port和client name;本文介绍是redis4.0之前的输出字段）
每条slowlog输出共4个字段，其中第4个字段可有有1~N个输出子字段;
下面示例中，第一个HGET命令为例分析：
字段1：这个命令出现在slowlog的序号,server启动后每产生一条slowlog就递增, 当前为6.
字段2：命令执行时的Unix时间戳.
字段3：命令执行微妙数,当前是74372微妙,约74ms.
字段4: 命令及其参数,如果参数很多或很大,只会显示部分并给出省略参数个数;
当前命令是”hgetall” “max.dsp.blacklist”
示例：获取最近2个慢查询命令 127.0.0.1:6381> SLOWLOG get 2 1) 1) (integer) 6 序号 2) (integer) 1458734263 unix时间戳 3) (integer) 74372 耗时微秒数 4) 1) "hgetall" 命令及期参数(以容量切分为小字段） 2) "max.dsp.blacklist" 2) 1) (integer) 5 2) (integer) 1458734258 3) (integer) 5411075 4) 1) "keys" 2) "max.dsp.blacklist"
redis slowlog耗时的实际含义
如MySQL/MongoDB等常见数据库，慢查询的query_time都会包含命令所有耗时，包含锁等待这类时间； 而redis的慢查询query_time只记录自己“被cpu服务的时间”，不包含排队等待、IO(aof,网络IO)等待这类时间。理解这点非常重要, 这就是文章开始时提出问题。
我们再来看官方文档内容：”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).“
Queueing Delay
Queueing Delay(后文称:排队延迟）是在Thinking Clearly About Performance
Paper和《Systems Performance:Enterprise and the Cloud》书中有提出；
在并发系统中，工作量对某类资源请求超过其所能处理的程度(即饱和度）,请求就会出现排队等待，请求等待被服务的时间(Q)就叫排队延迟。
queueing delay: time spent waiting in a queue
for access to a shared resource.
图1：Response time with queueing delay]
在图中「M/M/8」排列模型中，当资源使用率达到饱和度，请求开始出现排队等待。设定请求的响应时间(R),服务时间(S), 排队延时（Q).
R = S + Q
我们回到redis的slowlog问题上，前面已分析slowlog只计算redis命令被服务的时间，并不包含命令的排队延迟时间。
做个测试：
1 redis实例port=6386,分别打开两个session. session-1模拟一个执行耗时6秒的大命令debug sleep 6；隔几秒后session-2执行一个简单的set a b的命令。
2 使用Percona tcprstat监控redis的响应时间(TCP响应时间)
3 两个sessions的命令执行完成后，查看redis slowlog记录的命令耗时（slowlog-log-slower-than设置0）
测试结论:
从redis响应时间监控(min列），可见set a b命令耗时1530357微秒(约1.53秒）；但从redis slowlog中查看set a b命令耗时为8微秒，可见slowlog没有记录set命令排队延迟等待的时间。
因Redis是单线程模型，debug sleep阻塞了set命令，set命令的整体响应时间(R)是1530357微秒，而其服务时间(S)为8微秒，排队延迟(Q)为1530349微秒。
测试过程如下：
Session-1:
127.0.0.1:6386> debug sleep 6 模拟一个6秒的大请求(禁止在生产环境尝试）
OK
(6.00s)
Session-2:
127.0.0.1:6386> set a b
OK
(1.53s)
Redis Slowlog:
127.0.0.1 :6386> SLOWLOG get 查看实际的耗时
1) 1) (integer) 10
2) (integer) 1474684074
3) (integer) 8
4) 1) “set”
2) “a”
3) “b”
2) 1) (integer) 9
2) (integer) 1474684074
3) (integer) 6000116
4) 1) “debug”
2) “sleep”
3) “6”
Redis的响应时间监控：
图2 tcprstat监控redis的响应时间
从图2，tcp监控可见，共2个请求：max对应debug命令约6秒，min对应set命令约1.53秒；但set在慢查询中实际记录8微秒，只记录它使用cpu的耗时，这1.53秒基本全是等待debug命令的排队时间Q。所以从请求redis的应用服务角度看，set命令响应时间是1.53秒。
如文章开始的问题，当redis因CPU资源过载出现性能拐点，或因某个耗时很大命令，导致所有redis请求排队等待，redis的响应时间会变得很坏；但可能只有少量或没有slowlog记录。
redis是single-threaded服务
redis server是单线程(single-threaded)服务(除少量bio操作），即同一时刻只能处理一个命令，并且单个命令执行完成后，才会响应其他命令。
图3：单线程服务排队(来自:Queueing Theory)
如图3，单线程服务同一时刻只能处理一个task，如果某个task耗时很大，就导致所有请求排队等待；所以RD和DBA在设计keyspace和访问模式时，应尽量避免使用耗时较大的命令。
在理想状态下，redis单实例能处理8~10w的QPS, 如果大量的redis命令大量耗时大于1ms, 其实QPS只能达到1000基于几百。
redis出现耗时大的命令，导致其他所有请求被阻塞等待，redis处理能力急剧退化，易导致整个服务链雪崩。
单线程服务的throughput优化
从<Queueing Theory in practice>给出的单线程服务响应时间(W)、命令的服务时间(S)、服务的thoughput（λ ）的计算公式如下图4
图4：single-server排队模型
通过公式可见，当优化命令的服务时间S降低一半时，整个服务能提高的QPS(λ )量是1倍，同时响应时间W更低。
所以redis服务优化时，优化响应时间最长指令，对提搞redis整体QPS和响应效率改善最有效的方式。
总结
redis slowlog耗时只记录命令被CPU服务时间；
redis服务层要监控实际耗时，通过类似tcprstat或packetbeats工具；
在优化redis性能，即吞吐量和响应时间；重点优化耗时大的指令；业务在设计keyspace模型时，尽量避免高时间复杂度命令，或大集合类型做好边界检查；
需理解redis的单线程排队延时理论。
参考：
1 <Queueing Theory in practice> by Eben Freeman
本系列文章：
