Redis: “psync scheduled to be closed ASAP for overcoming of output buffer limits” and the client-output-buffer-limit

We have a Redis-cluster with Master-slave replication and Sentinel, see the Redis: replication, part 2 – Master-Slave replication, and Redis Sentinel, Redis: fork – Cannot allocate memory, Linux, virtual memory and vm.overcommit_memory, and Redis: main configuration parameters and performance tuning overview posts.

The system worked great until we started using it much more actively.

Redis info

A few useful troubleshooting commands.

To check all keys in all database use the INFO command:

And keys size – with the bigkeys command:

The usfull option --stat:

And a monitor:

And slowlog:

Also, check the latency.

Now, let’s go to the error.

The “psync scheduled to be closed ASAP for overcoming of output buffer limits” error

On one calm evening, our monitoring sends an alert that the cluster is down.

Redis master log during that issue was:

From all the text about we are most interested in the  “psync scheduled to be closed ASAP for overcoming of output buffer limits” message.

A “quick-fix” – client-output-buffer-limit

The solution is to increase the client-output-buffer-limit.

In short, it is a buffer used by the Redis Master to store a data that was changed during synchronization with its slave.

Check it current value:

The format here:

client-output-buffer-limit <class> <hard limit> <soft limit> <soft seconds>

And default values:

• client-output-buffer-limit normal 0 0 0
• client-output-buffer-limit slave 256mb 64mb 60
• client-output-buffer-limit pubsub 32mb 8mb 60

With such settings, a connection to a slave will be closed immediately if the <hard limit> – 256 MB – reached, or if the <soft limit> – 64 MB – exceeded over time from the  <soft seconds> – 60 seconds.

For us – we need to increase values in the slave 268435456 67108864 60.

On the Master host set a new value, 512 MB:

Actually, I had to increase the buffer up to the 512 MB, then 1 GB, and 2… and 4, 8 – and only with the 10 BG the service was able to finish the synchronization prcoess., although data in memory was only about 5 GB:

And a slave’s log:

And now, when Production went back to live, let’s go deeper into the issue.

What’s going on?

Redis master-slave – the synchronization process explained

Let’s see steps on how the synchronization process is performed:

1. a Slave on a start or after disconnect goes to a Master and ask to send him Master’s database
2. a Master replies to this request and:
   1. creates a child process to create its database dump onto a filesystem as a  dump.rdb file (see the fork() vs fork() vs clone())
   2. during this time Master will proceed its work with currently connected clients
   3. and all the data that was changed in its dataset during the dump creation will be saved to the replication buffer
3. Master sends a notification that the dump is ready to the Slave and the Slave starts copying the dump over the network to save it on a disk of the Slave’s host
4. the Slave finishes dump copy, loads it to its Redis instance memory and send a notification to the Master that the Slave is ready to serve clients
5. Master in its turn checks its replication buffer and if there are any data – Master starts sending the changed data from the buffer to the Slave, so the Slave can replace the data in its memory with new, actualized, data from the Master
6. the Slave applies those changes and starts its work

Thus, the replication process consists of two parts:

1. at first, a full database copy is created, which may contain some outdated data (was changed during a dump creation and transferring)
2. after that, a consistent update from a buffer is applied to the data on a Slave to make it the same as it is in a Master ‘s database

A database and buffer size

The first issue is that sometimes Redis needs in x3 memory comparing to its database size to create a dump, and the second – and the main issue – is that fact that while a dump will be created, and then transferred to a slave with all the network’s delays and will be saved to a Slave’s hard disk – the data on a Master can be changed.

So, during the dump transition – all such changes on a Master Redis instance will be stored in the Replication buffer. But once it will be exhausted – it will be purged and the synchronization process will start over. And over. And again.

In theory, the buffer’s size must be not less than a database’s size, although there is really little chance that all the data in the database will be updated during sync.

In any case, it’s all really rough estimations and you’ll have to test and monitor your real usage to get the real value for the buffer size.

But here is a couple of steps that can help you in such an investigation.

Check the current size of a database in a Master’s memory:

Create its dump:

Check the RDB (a dump’s) file size:

So, in memory we have 830 MB database, but in the configuration, we have memory limit up to the 50% of the hots’s memory:

So, the database can grow up to the ~16 GB (the server has 32 GB mem in total), and after a dump will be created – its size will be about 7-8 GB.

Now, we need to get a rough estimation time of the network transfer process, and knowing the maximal file size to be transferred – let’s calculate the time needed to finish it.

To check the connection speed – the iperf tool can be used, install it on a Slave and Master:

On the Master host – run  iperf in the server’s mode:

Позже наткнулся на redis-cli --latency -h <Redis IP> -p <Redis port>

And run it from the Slave as a client:

4.90 Gbits/sec – 625 MBytes/sec.

Knowing the fact that the dump’s size will be about 7 GB we can use the calculator here>>> – 13 seconds to transfer it.

Now, using the --stat we can check how many keys are updated on the Master in one second:

530178 – 530407 == 229 keys per second.

Or you can use monitoring tools like Prometheus and redis-exporter, and then select all the SET-requests as this are the main update’s requests:

irate(redis_commands_total{instance="production.bttrm-production-console",job="redis-exporter-cluster",cmd="set"}[1m])

And find keys size:

229 by the ~4.5 MB == around 1 GB changed data will be added to the buffer during those 13 seconds for the transfer.

But, again – this is very rough calculations as we are counting operations during a normal workload, while sometimes it can be in a few times bigger.

Useful links

• Redis Clients Handling
• Client Buffers-Before taking Redis in production check this!
• Top Redis Headaches for Devops – Replication Buffer
• Redis latency problems troubleshooting
• The Endless Redis Replication Loop: What, Why and How to Solve It (slave-output-buffer-throttling wasn’t added to Redis, but the post is really interesting)
• 6 Crucial Redis Monitoring Metrics You Need To Watch
• How to collect Redis metrics
• How to Benchmark the Performance of a Redis Server
• Some interesting redis-cli commands and usages

Also published on Medium.