Redis Slowlog

Redis’ slow query logging feature is used to log command requests that take longer than a given amount of time to execute, which can be used to analyze and optimize query speed. In this article, we will analyze how Redis’ slow query logging feature is implemented.

Redis provides two configuration options for slow logging.

• slowlog-log-slower-than: specifies how many microseconds a command request will be logged if it takes longer than 10,000 microseconds to execute, the default is 10,000 microseconds.
• slowlog-max-len: Specifies the maximum number of slow query logs that the server will keep. When the number of slow query logs stored by Redis reaches the specified value, the server will delete the oldest slow query log before adding a new one.

We can use the CONFIG SET/GET command to set/get the values of these two options. Note that the slow query log is stored in memory and not in a log file , which ensures that the slow query log does not become a bottleneck for speed.

Data Structures

The data structure of slowlog is defined in the redisServer structure.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

struct redisServer {
    ...
    // A linked list that holds all slow query logs
    list *slowlog;                  /* SLOWLOG list of commands */
    // ID of the next slow query log
    long long slowlog_entry_id;     /* SLOWLOG current entry ID */
    // The server configures the value of the slowlog-log-slower-than option
    long long slowlog_log_slower_than; /* SLOWLOG time limit (to get logged) */
    // The server configures the value of the slowlog-max-len option
    ...
};

It can be seen that the slowlog is stored inside a doubly linked list to facilitate the insertion of new logs at the head of the table, and will be deleted from the end of the table when the amount of logs reaches the set storage limit.

The data of a slowlog is stored in the structure slowlogEntry, which holds the parameters of the timeout command, duration, log ID, client and other information.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16

typedef struct slowlogEntry {
    // Commands and Parameters
    robj **argv;
    // Number of commands and command parameters
    int argc;
    // Log ID
    long long id;       /* Unique entry identifier. */
    // The time consumed to execute the command, in microseconds
    long long duration; /* Time spent by the query, in microseconds. */
    // UNIX timestamp of the command execution
    time_t time;        /* Unix time at which the query was executed. */
    // Client Name
    sds cname;          /* Client name. */
    // Client Address
    sds peerid;         /* Client network address. */
} slowlogEntry;

The value of a slowlog linked list is a pointer to the log node slowlogEntry, which together form the data structure of the slow query log. When a new log needs to be added, the add new node function of the linked list is called and the pointer is added to the linked list header.

1
2
3
4
5
6

slowlogEntry *slowlogCreateEntry(client *c, robj **argv, int argc, long long duration) {
    slowlogEntry *se = zmalloc(sizeof(*se));
    ...
    return se;
}
listAddNodeHead(server.slowlog,slowlogCreateEntry(c,argv,argc,duration));

And why is redisServer.slowlog_entry_id the ID of the next log? This is a C syntax issue and the specific code used to set the log ID is as follows.

1

se->id = server.slowlog_entry_id++;

This line of code will first assign the value of server.slowlog_entry_id to se.id and then add 1 to its own value (I always feel a little awkward writing this)

Adding Logs

During the initialization of the Redis service, the initialization function for the slow query function is also executed, creating an empty doubly linked list.

1
2
3
4
5

void slowlogInit(void) {
    server.slowlog = listCreate();
    server.slowlog_entry_id = 0;
    listSetFreeMethod(server.slowlog,slowlogFreeEntry);
}

When the client sends a command to the server, the control flow is handed over to server.c/call, which calls the command implementation function to execute the command and calculates the time taken to execute the command, which is handed over to the slowlog function.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

void call(client *c, int flags) {
    start = server.ustime;
    c->cmd->proc(c);
    // Calculate the time taken for command execution
    duration = ustime()-start;
    slowlogPushEntryIfNeeded(c,c->argv,c->argc,duration);
    ...
}

void slowlogPushEntryIfNeeded(client *c, robj **argv, int argc, long long duration) {
    // Slow query function is not turned on, return directly
    if (server.slowlog_log_slower_than < 0) return; /* Slowlog disabled */
    // If the execution time exceeds the limit set by the server, then the command is added to the slow query log
    if (duration >= server.slowlog_log_slower_than)
        // New log added to linked list header
        listAddNodeHead(server.slowlog,
                        slowlogCreateEntry(c,argv,argc,duration));

    /* Remove old entries if needed. */
    // If the number of logs is too large, then delete
    while (listLength(server.slowlog) > server.slowlog_max_len)
        listDelNode(server.slowlog,listLast(server.slowlog));
}

As you can see from the summary code above, the specific logic is left to the slowlogPushEntryIfNeeded() function, which adds a new log when the command times out and removes it if the number of logs reaches the limit.

The logic of slowlog implementation is easy to understand. If the timeout is reached, a new element is added to the head of the linked list, and if the number of logs reaches the upper limit, an element is removed from the end of the linked list, probably due to the single-threaded design of Redis, which avoids concurrency problems.

Reference

• https://wingsxdu.com/posts/database/redis/slowlog/