redis 慢日志查询

方式一:Redis提供命令统计工具:

info commandstats

10.1.5.102:6380> info commandstats
# Commandstats
cmdstat_get:calls=912783,usec=2197452,usec_per_call=2.41
cmdstat_setex:calls=144861,usec=573205,usec_per_call=3.96
cmdstat_del:calls=4346,usec=73850066,usec_per_call=16992.65
cmdstat_rpush:calls=24802058,usec=84987995,usec_per_call=3.43
cmdstat_llen:calls=490,usec=1107,usec_per_call=2.26
cmdstat_lrange:calls=271,usec=3001,usec_per_call=11.07
cmdstat_zadd:calls=1374572,usec=9954846,usec_per_call=7.24
cmdstat_zrem:calls=8962,usec=72692,usec_per_call=8.11
cmdstat_zrange:calls=10838,usec=211446,usec_per_call=19.51
cmdstat_zrevrange:calls=71516,usec=358102,usec_per_call=5.01
cmdstat_zcard:calls=107735,usec=489725,usec_per_call=4.55
cmdstat_hset:calls=2606922687,usec=3831922960,usec_per_call=1.47
cmdstat_hsetnx:calls=22564412,usec=36307426,usec_per_call=1.61
cmdstat_hget:calls=20238310,usec=55742113,usec_per_call=2.75
cmdstat_hmset:calls=26,usec=184784,usec_per_call=7107.08
cmdstat_hmget:calls=3636971,usec=442575977,usec_per_call=121.69
cmdstat_hdel:calls=282991,usec=26254221,usec_per_call=92.77
cmdstat_hlen:calls=56,usec=170,usec_per_call=3.04
cmdstat_hkeys:calls=596,usec=8339530,usec_per_call=13992.50
cmdstat_hgetall:calls=24111886,usec=343261103,usec_per_call=14.24
cmdstat_hscan:calls=967,usec=19921444,usec_per_call=20601.29
cmdstat_randomkey:calls=100,usec=244,usec_per_call=2.44
cmdstat_select:calls=105,usec=129,usec_per_call=1.23
cmdstat_expire:calls=67,usec=280,usec_per_call=4.18
cmdstat_keys:calls=29,usec=36811,usec_per_call=1269.34
cmdstat_scan:calls=19,usec=165128,usec_per_call=8690.95
cmdstat_dbsize:calls=26,usec=29,usec_per_call=1.12
cmdstat_ping:calls=1430971,usec=1579668,usec_per_call=1.10
cmdstat_save:calls=1,usec=52232827,usec_per_call=52232828.00
cmdstat_type:calls=157,usec=429,usec_per_call=2.73
cmdstat_info:calls=108694,usec=8107526,usec_per_call=74.59
cmdstat_ttl:calls=55,usec=137,usec_per_call=2.49
cmdstat_persist:calls=2606922634,usec=1357082035,usec_per_call=0.52
cmdstat_config:calls=3,usec=82,usec_per_call=27.33
cmdstat_subscribe:calls=914,usec=8477,usec_per_call=9.27
cmdstat_publish:calls=4929601,usec=31304224,usec_per_call=6.35
cmdstat_restore:calls=11,usec=13484,usec_per_call=1225.82
cmdstat_client:calls=24,usec=33,usec_per_call=1.38
cmdstat_slowlog:calls=11,usec=920,usec_per_call=83.64
cmdstat_command:calls=7,usec=4382,usec_per_call=626.00

通过这个工具可以查看所有命令统计的快照，比如命令执行了多少次，执行命令所耗费的微秒数(每个命令的总时间和平均时间)

由上面可以看到cmdstat_save命令非常慢，平均用时52232828.00微秒，这个慢命令会阻塞后边的命令。

 

方式二:Redis-慢查询分析

一.慢查询日志
慢查询日志帮助开发和运维人员定位系统存在的慢操作。慢查询日志就是系统在命令执行前后计算每条命令的执行时间，当超过预设阀值，就将这条命令的相关信息（慢查询ID，发生时间戳，耗时，命令的详细信息）记录下来。Redis客户端一条名利分为如下四部分执行：

 

需要注意的是，慢查询日志只是统计步骤3）执行命令的时间，所以慢查询并不代表客户端没有超时问题。

二. 慢查询的配置参数
2.1 慢查询的预设阀值  slowlog-log-slower-than
slowlog-log-slower-than参数就是预设阀值，单位是微秒,默认值是1000，如果一条命令的执行时间超过10000微妙，那么它将被记录在慢查询日志中。

如果slowlog-log-slower-than的值是0，则会记录所有命令。

如果slowlog-log-slower-than的值小于0，则任何命令都不会记录日志。

 

2.2 慢查询日志的长度slowlog-max-len
slowlog-max-len只是说明了慢查询日志最多存储多少条。Redis使用一个列表来存储慢查询日志，showlog-max-len就是列表的最大长度。当慢查询日志已经到达列表的最大长度时，又有慢查询日志要进入列表，则最早插入列表的日志将会被移出列表，新日志被插入列表的末尾。

 

三 慢查询日志的组成
慢查询日志由以下四个属性组成：标识ID，发生时间戳，命令耗时，执行命令和参数

四 慢查询日志的访问和管理
4.1 获取慢查询日志slowlog get [n]
命令：slowlog get [N]

选型：N，可选，代表获取的日志条数

例如：

showlog get 5

返回：

执行导出:

 

4.2 获取慢查询日志列表的当前长度slowlog len
命令：

slowlog len

返回：2

 

4.3 慢查询日志重置slowlog reset
慢查询日志重置实际是对列表做清理操作。

命令：

slowlog reset

例如：slowlog reset

           slowlog len

返回： 0

 

五 慢查询日志最佳实践
（1）slowlog-max-len的设置建议

线上环境建议调大慢查询日志的列表，记录慢查询日志时Redis会对长命令做截断操作，并不会占用大量内存。增大慢查询列表可以减缓慢查询被剔除出列表的可能性。例如线上可以设置为1000以上。

（2）slowlog-log-lower-than的设置建议

需要根据redis的并发量调整该值。由于redis采用单线程响应名利，对于高流量的场景，如果执行命令的时间在1毫秒以上，那么redis最多可支撑OPS（每秒操作次数）不到1000，因此高OPS场景的REDIS建议设置为1毫秒。

（3）慢查询只记录命令执行时间，并不包括命令排队时间和网络传输时间。因此客户端

命令的执行时间要大于redis服务器实际执行命令的时间。因为命令执行排队极致，慢查询会导致命令级联阻塞，因此当客户端出现请求超时，需要检查该时间点是否有对应的慢查询，从而分析是否因为慢查询导致的命令级联阻塞

（4）慢查询日志是一个先进先出队列，慢查询较多的情况下，可能会丢失部分慢查询命令，可以定期执行slow get命令将慢查询日志持久化到其他存储中。然后制作可视化界面查询。