Redis慢查询日志

转载于http://www.seiang.com/?p=301

一、什么是慢查询日志？

slow log是Redis用来记录查询执行时间超过给定时长的命令请求的日志系统。许多数据库(如:MySQL)提供慢查询日志帮助开发与运维人员定位系统存在的慢操作。所谓慢查询日志就是系统在命令执行前后计算每条命令的执行时间,当超过预设阈值,就将这条命令的相关信息(例如:发生时间,耗时,命令的详细信息)记录到慢查询日志中，Redis也提供了类似的功能；另外，slow log保存在内存里面，读写速度非常快，因此你可以放心地使用它，不必担心因为开启slow log而损害Redis的速度。

二、Redis命令执行流程

1、发送命令

2、命令排队

3、命令执行

4、返回结果
注意：慢查询只统计步骤3的时间,所以没有慢查询并不代表客户端没有超时问题。换句话说。redis的慢查询记录时间指的是不包括像客户端响应、发送回复等IO操作，而单单是执行一个查询命令所耗费的时间。

三、设置和查看SLOWLOG

服务器配置有两个和慢查询日志相关的参数选项：

• slowlog-log-slower-than：选项指定执行时间超过多少微秒（默认1秒=1,000,000微秒）的命令请求会被记录到日志上。
  举个例子， 如果这个选项的值为100，那么执行时间超过100微秒的命令就会被记录到慢查询日志； 如果这个选项的值为500 ， 那么执行时间超过500微秒的命令就会被记录到慢查询日志； 诸如此类。
  注意：如果slowlog-log-slower-than=0会记录所有命令,slowlog-log-slower-than<0对于任何命令都不会进行记录.
• slowlog-max-len：选项指定服务器最多保存多少条慢查询日志。服务器使用先进先出的方式保存多条慢查询日志： 当服务器储存的慢查询日志数量等于slowlog-max-len选项的值时，服务器在添加一条新的慢查询日志之前，会先将最旧的一条慢查询日志删除。
  举个例子， 如果服务器slowlog-max-len的值为100，并且假设服务器已经储存了100条慢查询日志， 那么如果服务器打算添加一条新日志的话，它就必须先删除目前保存的最旧的那条日志， 然后再添加新日志。

在Redis中有两种修改配置的方法,一种是修改配置文件,另一种是使用config set命令动态修改；

1. config set slowlog-log-slower-than 20000
2. config set slowlog-max-len 1024
3. config rewrite

注意：如果需要将Redis将配置持久化到本地配置文件,要执行config rewrite命令

虽然慢查询日志存放在Redis内存列表中,但是Redis并没有暴露这个列表的键,而是通过一组命令来实现对慢查询日志的访问和管理.

(1) 获取慢查询日志

slowlog get n (参数n用来指定查询的条数)

1. 127.0.0.1:6379> slowlog get
2. 1) 1) (integer) 8 #日志的唯一标识符
3. 2) (integer) 1550636908 #命令执行是的UNIX时间戳
4. 3) (integer) 113359 #命令执行的时长，单位微妙
5. 4) 1) "slowlog" #执行的命令及命令参数
6. 2) "get"
7. 5) "127.0.0.1:59282"
8. 6) ""
9. 2) 1) (integer) 7
10. 2) (integer) 1550636874
11. 3) (integer) 35369
12. 4) 1) "CONFIG"
13. 2) "GET"
14. 3) "slowlog-log-slower-than"
15. 5) "127.0.0.1:59282"
16. 6) ""
17. 3) 1) (integer) 6
18. 2) (integer) 1542409903
19. 3) (integer) 154936
20. 4) 1) "REPLCONF"
21. 2) "ACK"
22. 3) "7677418"
23. 5) "127.0.0.1:36457"
24. 6) ""
25. 4) 1) (integer) 5
26. 2) (integer) 1538705609
27. 3) (integer) 53655
28. 4) 1) "REPLCONF"
29. 2) "ACK"
30. 3) "2503774"
31. 5) "127.0.0.1:36457"
32. 6) ""
33. 5) 1) (integer) 4
34. 2) (integer) 1538316696
35. 3) (integer) 124241
36. 4) 1) "REPLCONF"
37. 2) "ACK"
38. 3) "1960644"
39. 5) "127.0.0.1:45997"
40. 6) ""
41. 6) 1) (integer) 3
42. 2) (integer) 1537459324
43. 3) (integer) 161244
44. 4) 1) "REPLCONF"
45. 2) "ACK"
46. 3) "763182"
47. 5) "127.0.0.1:36457"
48. 6) ""
49. 7) 1) (integer) 2
50. 2) (integer) 1537293989
51. 3) (integer) 108165
52. 4) 1) "REPLCONF"
53. 2) "ACK"
54. 3) "532252"
55. 5) "127.0.0.1:36457"
56. 6) ""
57. 8) 1) (integer) 1
58. 2) (integer) 1536932942
59. 3) (integer) 37250
60. 4) 1) "REPLCONF"
61. 2) "ACK"
62. 3) "28028"
63. 5) "127.0.0.1:36457"
64. 6) ""
65. 9) 1) (integer) 0
66. 2) (integer) 1536912894
67. 3) (integer) 12932
68. 4) 1) "CONFIG"
69. 2) "GET"
70. 3) "dir"
71. 5) "127.0.0.1:46522"
72. 6) ""

1. 127.0.0.1:6379> slowlog get 2
2. 1) 1) (integer) 8
3. 2) (integer) 1550636908
4. 3) (integer) 113359
5. 4) 1) "slowlog"
6. 2) "get"
7. 5) "127.0.0.1:59282"
8. 6) ""
9. 2) 1) (integer) 7
10. 2) (integer) 1550636874
11. 3) (integer) 35369
12. 4) 1) "CONFIG"
13. 2) "GET"
14. 3) "slowlog-log-slower-than"
15. 5) "127.0.0.1:59282"
16. 6) ""

(2) 获取慢查询日志列表当前数量

1. slowlog len
2. 127.0.0.1:6379> slowlog len
3. (integer) 9

(3) 慢查询日志重置

1. slowlog reset
2. 127.0.0.1:6379> slowlog reset
3. OK
4. 127.0.0.1:6379> slowlog len
5. (integer) 0

在生产环境中，慢查询功能可以有效地帮助我们找到Redis可能存在的瓶颈，但在实际使用过程中要注意以下几点:

1、slowlog-max-len：线上建议调大慢查询列表，记录慢查询时Redis会对长命令做阶段操作,并不会占用大量内存.增大慢查询列表可以减缓慢查询被剔除的可能，例如线上可设置为1000以上.

2、slowlog-log-slower-than：默认值超过10毫秒判定为慢查询,需要根据Redis并发量调整该值.

3、慢查询只记录命令的执行时间,并不包括命令排队和网络传输时间.因此客户端执行命令的时间会大于命令的实际执行时间.因为命令执行排队机制,慢查询会导致其他命令级联阻塞,因此客户端出现请求超时时,需要检查该时间点是否有对应的慢查询,从而分析是否为慢查询导致的命令级联阻塞.

4、由于慢查询日志是一个先进先出的队列,也就是说如果慢查询比较多的情况下,可能会丢失部分慢查询命令,为了防止这种情况发生,可以定期执行slowlog get命令将慢查询日志持久化到其他存储中(例如:MySQL等)，然后可以通过可视化工具进行查询.