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等)，然后可以通過可視化工具進行查詢.