慢查询日志

Redis 的慢查询日志功能用于记录执行时间超过给定时长的命令请求，用户可以通过这个功能产生的日志来监视和优化查询速度。

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

  • slowlog-log-slower-than 选项指定执行时间超过多少微秒（1 秒等于 1,000,000 微秒）的命令请求会被记录到日志上。

举个例子，如果这个选项的值为 100 ，那么执行时间超过 100 微秒的命令就会被记录到慢查询日志；如果这个选项的值为 500 ，那么执行时间超过 500 微秒的命令就会被记录到慢查询日志；诸如此类。

  • slowlog-max-len 选项指定服务器最多保存多少条慢查询日志。

服务器使用先进先出的方式保存多条慢查询日志：当服务器储存的慢查询日志数量等于 slowlog-max-len 选项的值时，服务器在添加一条新的慢查询日志之前，会先将最旧的一条慢查询日志删除。

举个例子，如果服务器 slowlog-max-len 的值为 100 ，并且假设服务器已经储存了 100 条慢查询日志，那么如果服务器打算添加一条新日志的话，它就必须先删除目前保存的最旧的那条日志，然后再添加新日志。

让我们来看一个慢查询日志功能的例子，首先用 CONFIG_SET 命令将 slowlog-log-slower-than 选项的值设为 0 微秒，这样 Redis 服务器执行的任何命令都会被记录到慢查询日志中，接着将 slowlog-max-len 选项的值设为 5 ，让服务器最多只保存 5 条慢查询日志：

  1. redis> CONFIG SET slowlog-log-slower-than 0
  2. OK
  3.  
  4. redis> CONFIG SET slowlog-max-len 5
  5. OK

接着，我们用客户端发送几条命令请求：

  1. redis> SET msg "hello world"
  2. OK
  3.  
  4. redis> SET number 10086
  5. OK
  6.  
  7. redis> SET database "Redis"
  8. OK

然后使用 SLOWLOG GET 命令查看服务器所保存的慢查询日志：

  1. redis> SLOWLOG GET
  2. 1) 1) (integer) 4               # 日志的唯一标识符（uid）
  3.    2) (integer) 1378781447      # 命令执行时的 UNIX 时间戳
  4.    3) (integer) 13              # 命令执行的时长，以微秒计算
  5.    4) 1) "SET"                  # 命令以及命令参数
  6.       2) "database"
  7.       3) "Redis"
  8. 2) 1) (integer) 3
  9.    2) (integer) 1378781439
  10.    3) (integer) 10
  11.    4) 1) "SET"
  12.       2) "number"
  13.       3) "10086"
  14. 3) 1) (integer) 2
  15.    2) (integer) 1378781436
  16.    3) (integer) 18
  17.    4) 1) "SET"
  18.       2) "msg"
  19.       3) "hello world"
  20. 4) 1) (integer) 1
  21.    2) (integer) 1378781425
  22.    3) (integer) 11
  23.    4) 1) "CONFIG"
  24.    2) "SET"
  25.    3) "slowlog-max-len"
  26.    4) "5"
  27. 5) 1) (integer) 0
  28.    2) (integer) 1378781415
  29.    3) (integer) 53
  30.    4) 1) "CONFIG"
  31.       2) "SET"
  32.       3) "slowlog-log-slower-than"
  33.       4) "0"

如果这时再执行一条 SLOWLOG GET 命令，那么我们将看到，上一次执行的 SLOWLOG GET 命令已经被记录到了慢查询日志中，而最旧的、编号为 0 的慢查询日志已经被删除，服务器的慢查询日志数量仍然为 5 条：

  1. redis> SLOWLOG GET
  2. 1) 1) (integer) 5
  3.    2) (integer) 1378781521
  4.    3) (integer) 61
  5.    4) 1) "SLOWLOG"
  6.       2) "GET"
  7. 2) 1) (integer) 4
  8.    2) (integer) 1378781447
  9.    3) (integer) 13
  10.    4) 1) "SET"
  11.       2) "database"
  12.       3) "Redis"
  13. 3) 1) (integer) 3
  14.    2) (integer) 1378781439
  15.    3) (integer) 10
  16.    4) 1) "SET"
  17.       2) "number"
  18.       3) "10086"
  19. 4) 1) (integer) 2
  20.    2) (integer) 1378781436
  21.    3) (integer) 18
  22.    4) 1) "SET"
  23.       2) "msg"
  24.       3) "hello world"
  25. 5) 1) (integer) 1
  26.    2) (integer) 1378781425
  27.    3) (integer) 11
  28.    4) 1) "CONFIG"
  29.    2) "SET"
  30.    3) "slowlog-max-len"
  31.    4) "5"

慢查询记录的保存

服务器状态中包含了几个和慢查询日志功能有关的属性：

  1. struct redisServer {
  2.  
  3.     // ...
  4.  
  5.     // 下一条慢查询日志的 ID
  6.     long long slowlog_entry_id;
  7.  
  8.     // 保存了所有慢查询日志的链表
  9.     list *slowlog;
  10.  
  11.     // 服务器配置 slowlog-log-slower-than 选项的值
  12.     long long slowlog_log_slower_than;
  13.  
  14.     // 服务器配置 slowlog-max-len 选项的值
  15.     unsigned long slowlog_max_len;
  16.  
  17.     // ...
  18.  
  19. };

slowlog_entry_id 属性的初始值为 0 ，每当创建一条新的慢查询日志时，这个属性的值就会用作新日志的 id 值，之后程序会对这个属性的值增一。

比如说，在创建第一条慢查询日志时，slowlog_entry_id 的值 0 会成为第一条慢查询日志的 ID ，而之后服务器会对这个属性的值增一；当服务器再创建新的慢查询日志的时候，slowlog_entry_id 的值 1 就会成为第二条慢查询日志的 ID ，然后服务器再次对这个属性的值增一，以此类推。

slowlog 链表保存了服务器中的所有慢查询日志，链表中的每个节点都保存了一个 slowlogEntry 结构，每个 slowlogEntry 结构代表一条慢查询日志：

  1. typedef struct slowlogEntry {
  2.  
  3.     // 唯一标识符
  4.     long long id;
  5.  
  6.     // 命令执行时的时间，格式为 UNIX 时间戳
  7.     time_t time;
  8.  
  9.     // 执行命令消耗的时间，以微秒为单位
  10.     long long duration;
  11.  
  12.     // 命令与命令参数
  13.     robj **argv;
  14.  
  15.     // 命令与命令参数的数量
  16.     int argc;
  17.  
  18. } slowlogEntry;

举个例子，对于以下慢查询日志来说：

  1. 1) (integer) 3
  2. 2) (integer) 1378781439
  3. 3) (integer) 10
  4. 4) 1) "SET"
  5.    2) "number"
  6.    3) "10086"

图 23-1 展示的就是该日志所对应的 slowlogEntry 结构。

digraph { label = "\n 图 23-1 slowlogEntry 结构示例"; rankdir = LR; node [shape = record]; slowlogEntry [label = " slowlogEntry | id \n 3 | time \n 1378781439 | duration \n 10 | <argv> argv | argc \n 3 "]; argv [label = " { { argv[0] | StringObject \n \"SET\" } | { argv[1] | StringObject \n \"number\" } | { argv[2] | StringObject \n \"10086\" } } "]; slowlogEntry:argv -> argv;}

digraph { label = "\n 图 23-2 redisServer 结构示例"; rankdir = LR; node [shape = record]; redisServer [label = " redisServer | ... | slowlog_entry_id \n 6 | <slowlog> slowlog | slowlog_log_slower_than \n 0 | slowlog_max_len \n 5 | ... "]; slowlogEntry_5 [label = " slowlogEntry | id \n 5 | time \n 1378781521 | duration \n 61 | <argv> argv | argc \n 2 "]; slowlogEntry_1 [label = " slowlogEntry | id \n 1 | time \n 1378781425 | duration \n 11 | <argv> argv | argc \n 4 "]; more [label = "...", shape = plaintext] redisServer:slowlog -> slowlogEntry_5 -> more -> slowlogEntry_1;}

图 23-2 展示了服务器状态中，和慢查询功能有关的属性：

  • slowlog_entry_id 的值为 6 ，表示服务器下条慢查询日志的 id 值将为 6 。
  • slowlog 链表包含了 id 为 5 至 1 的慢查询日志，最新的 5 号日志排在链表的表头，而最旧的 1 号日志排在链表的表尾，这表明 slowlog 链表是使用插入到表头的方式来添加新日志的。
  • slowlog_log_slower_than 记录了服务器配置 slowlog-log-slower-than 选项的值 0 ，表示任何执行时间超过 0 微秒的命令都会被慢查询日志记录。
  • slowlog-max-len 属性记录了服务器配置 slowlog-max-len 选项的值 5 ，表示服务器最多储存五条慢查询日志。

注意

因为版面空间不足的缘故，所以图 23-2 展示的各个 slowlogEntry 结构都省略了 argv 数组。

慢查询日志的阅览和删除

弄清楚了服务器状态的 slowlog 链表的作用之后，我们可以用以下伪代码来定义查看日志的 SLOWLOG GET 命令：

  1. def SLOWLOG_GET(number=None):
  2.  
  3.     # 用户没有给定 number 参数
  4.     # 那么打印服务器包含的全部慢查询日志
  5.     if number is None:
  6.         number = SLOWLOG_LEN()
  7.  
  8.     # 遍历服务器中的慢查询日志
  9.     for log in redisServer.slowlog:
  10.  
  11.         if number <= 0:
  12.             # 打印的日志数量已经足够，跳出循环
  13.             break
  14.         else:
  15.             # 继续打印，将计数器的值减一
  16.             number -= 1
  17.  
  18.         # 打印日志
  19.         printLog(log)

查看日志数量的 SLOWLOG LEN 命令可以用以下伪代码来定义：

  1. def SLOWLOG_LEN():
  2.  
  3.     # slowlog 链表的长度就是慢查询日志的条目数量
  4.     return len(redisServer.slowlog)

另外，用于清除所有慢查询日志的 SLOWLOG RESET 命令可以用以下伪代码来定义：

  1. def SLOWLOG_RESET():
  2.  
  3.     # 遍历服务器中的所有慢查询日志
  4.     for log in redisServer.slowlog:
  5.  
  6.         # 删除日志
  7.         deleteLog(log)

添加新日志

在每次执行命令的之前和之后，程序都会记录微秒格式的当前 UNIX 时间戳，这两个时间戳之间的差就是服务器执行命令所耗费的时长，服务器会将这个时长作为参数之一传给 slowlogPushEntryIfNeeded 函数，而 slowlogPushEntryIfNeeded 函数则负责检查是否需要为这次执行的命令创建慢查询日志，以下伪代码展示了这一过程：

  1. # 记录执行命令前的时间
  2. before = unixtime_now_in_us()
  3.  
  4. # 执行命令
  5. execute_command(argv, argc, client)
  6.  
  7. # 记录执行命令后的时间
  8. after = unixtime_now_in_us()
  9.  
  10. # 检查是否需要创建新的慢查询日志
  11. slowlogPushEntryIfNeeded(argv, argc, before-after)

slowlogPushEntryIfNeeded 函数的作用有两个：

  • 检查命令的执行时长是否超过 slowlog-log-slower-than 选项所设置的时间，如果是的话，就为命令创建一个新的日志，并将新日志添加到 slowlog 链表的表头。
  • 检查慢查询日志的长度是否超过 slowlog-max-len 选项所设置的长度，如果是的话，那么将多出来的日志从 slowlog 链表中删除掉。以下是 slowlogPushEntryIfNeeded 函数的实现代码：
  1. void slowlogPushEntryIfNeeded(robj **argv, int argc, long long duration) {
  2.  
  3.     // 慢查询功能未开启，直接返回
  4.     if (server.slowlog_log_slower_than < 0) return;
  5.  
  6.     // 如果执行时间超过服务器设置的上限，那么将命令添加到慢查询日志
  7.     if (duration >= server.slowlog_log_slower_than)
  8.         // 新日志添加到链表表头
  9.         listAddNodeHead(server.slowlog,slowlogCreateEntry(argv,argc,duration));
  10.  
  11.     // 如果日志数量过多，那么进行删除
  12.     while (listLength(server.slowlog) > server.slowlog_max_len)
  13.         listDelNode(server.slowlog,listLast(server.slowlog));
  14. }

函数中的大部分代码我们已经介绍过了，唯一需要说明的是 slowlogCreateEntry 函数：该函数根据传入的参数，创建一个新的慢查询日志，并将 redisServer.slowlog_entry_id 的值增一。

举个例子，假设服务器当前保存的慢查询日志如图 23-2 所示，如果我们执行以下命令：

  1. redis> EXPIRE msg 10086
  2. (integer) 1

服务器在执行完这个 EXPIRE 命令之后，就会调用 slowlogPushEntryIfNeeded 函数，函数将为 EXPIRE 命令创建一条 id 为 6 的慢查询日志，并将这条新日志添加到 slowlog 链表的表头，如图 23-3 所示。

digraph { label = "\n 图 23-3 EXPIRE 命令执行之后的服务器状态"; rankdir = LR; node [shape = record]; redisServer [label = " redisServer | ... | slowlog_entry_id \n 7 | <slowlog> slowlog | slowlog_log_slower_than \n 0 | slowlog_max_len \n 5 | ... "]; slowlogEntry_6 [label = " slowlogEntry | id \n 6 | time \n 1378800320 | duration \n 14 | <argv> argv | argc \n 3 "]; slowlogEntry_1 [label = " slowlogEntry | id \n 1 | time \n 1378781425 | duration \n 11 | <argv> argv | argc \n 4 "]; more [label = "...", shape = plaintext] redisServer:slowlog -> slowlogEntry_6 -> more -> slowlogEntry_1;}

注意，除了 slowlog 链表发生了变化之外，slowlog_entry_id 的值也从 6 变为 7 了。

之后，slowlogPushEntryIfNeeded 函数发现，服务器设定的最大慢查询日志数目为 5 条，而服务器目前保存的慢查询日志数目为 6 条，于是服务器将 id 为 1 的慢查询日志删除，让服务器的慢查询日志数量回到设定好的 5 条。

删除操作执行之后的服务器状态如图 23-4 所示。

digraph { label = "\n 图 23-4 删除 id 为 1 的慢查询日志之后的服务器状态"; rankdir = LR; node [shape = record]; redisServer [label = " redisServer | ... | slowlog_entry_id \n 7 | <slowlog> slowlog | slowlog_log_slower_than \n 0 | slowlog_max_len \n 5 | ... "]; slowlogEntry_6 [label = " slowlogEntry | id \n 6 | time \n 1378800320 | duration \n 14 | <argv> argv | argc \n 3 "]; slowlogEntry_2 [label = " slowlogEntry | id \n 2 | time \n 1378781436 | duration \n 18 | <argv> argv | argc \n 3 "]; more [label = "...", shape = plaintext] redisServer:slowlog -> slowlogEntry_6 -> more -> slowlogEntry_2;}

重点回顾

  • Redis 的慢查询日志功能用于记录执行时间超过指定时长的命令。
  • Redis 服务器将所有的慢查询日志保存在服务器状态的 slowlog 链表中，每个链表节点都包含一个 slowlogEntry 结构，每个 slowlogEntry 结构代表一条慢查询日志。
  • 打印和删除慢查询日志可以通过遍历 slowlog 链表来完成。
  • slowlog 链表的长度就是服务器所保存慢查询日志的数量。
  • 新的慢查询日志会被添加到 slowlog 链表的表头，如果日志的数量超过 slowlog-max-len 选项的值，那么多出来的日志会被删除。