High latency during controlled failover in Redis cluster

[TerjeDahlstrom]

Promoting a replica to a master in a 3 + 3 cluster (By issuing cluster failover on a replica) during load causes some redis commands to freeze. After about 10 seconds, the operations finish. During the 10 seconds, new commands seem to be handled properly. I'm curious to what causes the commands to eventually finish, and if the 10 second delay is a result of a bug, or if it can be configured to be shorter in some way. When configuring Lettuce to have a, for our use case, reasonable timeout, which is significantly lower than 10 seconds, a RedisCommandTimeoutException is thrown instead which is similarly problematic.

See reproduction code as well as sample output below:

package test.reproducer;

import io.lettuce.core.RedisURI;
import io.lettuce.core.SetArgs;
import io.lettuce.core.TimeoutOptions;
import io.lettuce.core.cluster.ClusterClientOptions;
import io.lettuce.core.cluster.ClusterTopologyRefreshOptions;
import io.lettuce.core.cluster.RedisClusterClient;
import io.lettuce.core.cluster.api.StatefulRedisClusterConnection;

import java.time.Duration;
import java.time.Instant;
import java.util.UUID;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;

public class Main {

    private final StatefulRedisClusterConnection<String, String> connection;
    private final AtomicLong calls = new AtomicLong(0L);
    private final AtomicLong slowCalls = new AtomicLong(0L);
    private final AtomicLong badCalls = new AtomicLong(0L);
    private final AtomicLong callsIssued = new AtomicLong(0L);

    public static void main(String[] args) {
        var clusterRefreshOptions =
                ClusterTopologyRefreshOptions.builder().enablePeriodicRefresh(Duration.ofSeconds(3)).build();
        var timeoutOptions = TimeoutOptions.builder()
//                .fixedTimeout(Duration.ofMillis(1000))
                .build();
        var clientOptions = ClusterClientOptions.builder()
                .topologyRefreshOptions(clusterRefreshOptions).timeoutOptions(timeoutOptions).build();
        var clusterClient =
                RedisClusterClient.create(new RedisURI("<IP>", <PORT>, Duration.ofMillis(500)));
        clusterClient.setOptions(clientOptions);
        var main = new Main(clusterClient.connect());
        main.run();
    }

    public Main(StatefulRedisClusterConnection<String, String> connection) {
        this.connection = connection;
    }

    public void run() {
        ScheduledExecutorService executorService = Executors.newSingleThreadScheduledExecutor();
        executorService.scheduleAtFixedRate(this::callRedis, 500, 1, TimeUnit.MILLISECONDS);
        ScheduledExecutorService statsExecutorService = Executors.newSingleThreadScheduledExecutor();
        statsExecutorService.scheduleAtFixedRate(this::stats, 500, 1000, TimeUnit.MILLISECONDS);

    }

    private void stats() {
        System.out.println("Calls: " + calls.get() + " Bad calls: " + badCalls.get()
                + " Slow calls: " + slowCalls.get() + " Calls waiting: " + (callsIssued.get() - calls.get()));
    }

    private void callRedis() {
        callsIssued.incrementAndGet();
        var startTime = Instant.now();
        connection.async().set(UUID.randomUUID().toString(),
                        "A very reasonable value",
                        SetArgs.Builder.ex(Duration.ofSeconds(60)))
                .handle((s, e) -> {
                    if (Duration.between(startTime, Instant.now()).compareTo(Duration.ofSeconds(5)) > 0) {
                        slowCalls.incrementAndGet();
                    }
                    calls.incrementAndGet();
                    if (e != null) {
                        badCalls.incrementAndGet();
                    }
                    return s;
                });
    }
}

Output:

Calls: 14009 Bad calls: 0 Slow calls: 0 Calls waiting: 1
Calls: 15010 Bad calls: 0 Slow calls: 0 Calls waiting: 0
Calls: 16010 Bad calls: 0 Slow calls: 0 Calls waiting: 0
Calls: 16862 Bad calls: 0 Slow calls: 0 Calls waiting: 148
Calls: 17711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 18711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 19711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 20711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 21699 Bad calls: 0 Slow calls: 0 Calls waiting: 302
Calls: 22709 Bad calls: 0 Slow calls: 0 Calls waiting: 300
Calls: 23711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 24711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 25711 Bad calls: 0 Slow calls: 0 Calls waiting: 299
Calls: 27010 Bad calls: 0 Slow calls: 299 Calls waiting: 0
Calls: 28010 Bad calls: 0 Slow calls: 299 Calls waiting: 0
Calls: 29010 Bad calls: 0 Slow calls: 299 Calls waiting: 0

[TerjeDahlstrom]

This ended up not being an issue with Lettuce. See #2572 for details.