Using the Redis NoSql database with .NET Part 15: logging slow queries

Introduction

In the previous post we looked at how to use the Redis messaging feature in the ServiceStack.Redis .NET client. We saw that it was in fact very easy to both send and receive messages with a couple of lines of code. The most important thing to keep in mind is that the subscriber application has a blocking call to the SubscribeToChannels function. It will prevent all other code after it from executing and start watching the declared Redis channel.

In this post we’ll look at how we can log slow queries in Redis.

The slow log

In this post we looked at the MONITOR command. It shows every command sent to the server with no filtering. An alternative to MONITOR is the slow log in Redis which logs commands that took longer than a certain time to execute. The Redis configuration file includes a section called “SLOW LOG” that documents the slow log pretty well. In the Windows port there are two configuration files: redis.windows.conf and redis.windows-service.conf. The two are identical but the latter one is used by the Redis Windows service. You can search for “slow log” in either file to quickly find the relevant section.

The slow log logs slow queries to memory, so the log is not persisted. What is meant by “slow” can be defined with the slowlog-log-slower-than parameter followed by a number in microseconds. By default it is set to 10000 which is one tenth of a second. One second is 100000 microseconds. The other relevant parameter is slowlog-max-len which specifies the maximum length of the slow log. The length of the log means the number of entries kept in the log. If this limit is reached then the oldest log entry is removed.

We can test this feature without editing the configuration file. We can set temporary configuration settings on a running Redis instance using the CONFIG SET command. So we can open up redis-cli and execute the following command:

CONFIG SET slowlog-log-slower-than 5

This sets the temporary slowness limit to 5 microseconds. I’d say that every command will take more than that. Let’s test a couple of commands from earlier posts:

SET customer-count “1534”
INCR customer-count
RPUSH todolist “shopping”
RPUSH todolist “sleeping”
SADD to-do-monday “cook” “study” “walk” “write” “study” “cook”
ZADD distance-from-budapest 445 “Prague”
HMSET country:1 capital “Tallinn” language “Estonian” local-name “Eesti” currency “Euro” dialing-code “+372” population “1317797” internet-code “.ee”

We open the slow log with the following command:

SLOWLOG GET

Which prints all entries in the slow log. We can supply and additional parameter to retrieve the n most recent entries:

SLOWLOG GET 5

Here’s one example from the output:

3) 1) (integer) 6
2) (integer) 1493265835
3) (integer) 75
4) 1) “ZADD”
2) “distance-from-budapest”
3) “445”
4) “Prague”

The first integer is a log entry ID, 6 in this example. Then comes a UNIX timestamp when the log entry was registered. The third integer is the query execution time in microseconds, i.e. 75 in this case. You’ll recognise the executed command and its arguments in the final section of the output.

We can check the current number of entries in the slow log with…

SLOWLOG LEN

…and we can remove all log entries with…

SLOWLOG RESET

We’ll continue in the next post.

You can view all posts related to data storage on this blog here.