Talk about redis slowlog and latency monitor

  redis

Order

This article mainly studies redis slowlog and latency monitor

slowlog

Redis introduced slowlog in version 2.2.12 to record commands that exceed the specified execution time. This execution time does not include IO operation time such as communication with the client, which is the actual command execution time. The main operations are as follows:

View the number of slowlog

127.0.0.1:6379> slowlog len
(integer) 1024

View slowlog execution time threshold

127.0.0.1:6379> config get slowlog-log-slower-than
1) "slowlog-log-slower-than"
2) "1000"

Set the slowlog execution time-consuming threshold.

127.0.0.1:6379> config set slowlog-log-slower-than 1000
OK

See the threshold for the number of slowlog saves.

127.0.0.1:6379> config get slowlog-max-len
1) "slowlog-max-len"
2) "1024"

Set the threshold for the number of slowlog saves.

127.0.0.1:6379> config set slowlog-max-len 1024
OK

Query slowlog

127.0.0.1:6379> slowlog get 1
1) 1) (integer) 76016
   2) (integer) 1537250266
   3) (integer) 48296
   4) 1) "COMMAND"

The first line is the command id, the second line is timestamp, the third line is the execution time, and the fourth line is the command and parameters

Clear slowlog record

127.0.0.1:6379> slowlog reset
OK

latency monitor

Redis introduced latency monitoring in version 2.8.13, which mainly monitors latency spikes (Delay glitch)。 It monitors based on the event mechanism. command event is the latency of monitoring command execution, fast-command event is the latency of monitoring commands with time complexity of O(1) and O(logN), and fork event is the latency of redis execution system call fork(2). The main operations are as follows:

Set up/open latency monitor

127.0.0.1:6379> config set latency-monitor-threshold 100
OK

Read latency monitor configuration

127.0.0.1:6379> config get latency-monitor-threshold
1) "latency-monitor-threshold"
2) "100"

Get the latest latency

127.0.0.1:6379> debug sleep 1
OK
(1.01s)
127.0.0.1:6379> debug sleep .25
OK
127.0.0.1:6379> latency latest
1) 1) "command"
   2) (integer) 1537268070
   3) (integer) 250
   4) (integer) 1010

Returns the event name, timestamp of occurrence, latest delay (Millisecond), maximum delay (Millisecond)

View the delay history of an event

127.0.0.1:6379> latency history command
1) 1) (integer) 1537268064
   2) (integer) 1010
2) 1) (integer) 1537268070
   2) (integer) 250

View event delay diagram

127.0.0.1:6379> latency reset command
(integer) 0
127.0.0.1:6379> debug sleep .1
OK
127.0.0.1:6379> debug sleep .2
OK
127.0.0.1:6379> debug sleep .3
OK
127.0.0.1:6379> debug sleep .4
OK
127.0.0.1:6379> debug sleep .5
OK
(0.50s)
127.0.0.1:6379> latency graph
(error) ERR syntax error
127.0.0.1:6379> latency graph command
command - high 500 ms, low 100 ms (all time high 500 ms)
--------------------------------------------------------------------------------
   _#
  _||
 _|||
_||||

22117
4062s
ssss

Reset/Empty Event Data

127.0.0.1:6379> latency reset command
(integer) 1
127.0.0.1:6379> latency history command
(empty list or set)
127.0.0.1:6379> latency latest
(empty list or set)

Diagnostic advice

127.0.0.1:6379> latency doctor
Dave, I have observed latency spikes in this Redis instance. You don't mind talking about it, do you Dave?

1. command: 6 latency spikes (average 257ms, mean deviation 142ms, period 3.83 sec). Worst all time event 500ms.

I have a few advices for you:

- Check your Slow Log to understand what are the commands you are running which are too slow to execute. Please check http://redis.io/commands/slowlog for more information.
- Deleting, expiring or evicting (because of maxmemory policy) large objects is a blocking operation. If you have very large objects that are often deleted, expired, or evicted, try to fragment those objects into multiple smaller objects.

Summary

  • Redis’ slowlog was introduced in version 2.2.12 and latency monitor was introduced in version 2.8.13
  • Slowlog only records the execution time of pure commands, excluding IO interaction with clients and fork of redis
  • Latency spikes monitored by latency monitor have a wider scope, including not only command execution, but also the time-consuming operations such as fork(2) system call and key expiration.

doc