Redis expired monitoring scenario

In the business, there is a need to wait for a certain time to execute a certain behavior, such as closing an order after 30 minutes. There are many demos that use Redis to expire and monitor, but in fact, this is a big hole, because Redis can't ensure that the key is deleted at the specified time, which also causes the delay of notification. Not much, run a test.

Test situation

First, the environment. Redis runs in the Docker container. It allocates a cpu and 512MB of memory. The result of executing redis benchmark-t set-r 100000-n 1000000 in Docker is as follows:

In fact, there are some imprecise benchmark threads that should not run inside the Docker container. During the score running, the benchmark and redis main threads each hold 50% of the CPU.

The test code is as follows:

@Service
@Slf4j
public class RedisJob {

@Autowired
private StringRedisTemplate stringRedisTemplate;

public DateTimeFormatter dateTimeFormatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss");
public LocalDateTime end = LocalDateTime.of(LocalDate.of(2020, 5, 12), LocalTime.of(8, 0));

@Scheduled(cron = "0 56 * * * ?")
public void initKeys() {
    LocalDateTime now = LocalDateTime.now();
    ValueOperations<String, String> operations = stringRedisTemplate.opsForValue();
    log.info("Start Setup key");
    LocalDateTime begin = now.withMinute(0).withSecond(0).withNano(0);
    for (int i = 1; i < 17; i++) {
        setExpireKey(begin.plusHours(i), 8, operations);
    }
    log.info("Setup complete: " + Duration.between(now, LocalDateTime.now()));
}

private void setExpireKey(LocalDateTime expireTime, int step, ValueOperations<String, String> operations) {
    LocalDateTime localDateTime = LocalDateTime.now().withNano(0);
    String nowTime = dateTimeFormatter.format(localDateTime);
    while (expireTime.getMinute() < 55) {
        operations.set(nowTime + "@" + dateTimeFormatter.format(expireTime), "A", Duration.between(expireTime, LocalDateTime.now()).abs());
        expireTime = expireTime.plusSeconds(step);
    }
}

}

It means that at 56 minutes per hour, a batch of key s that expire in the next 16 hours will be added. The expiration time interval is 8 seconds, and the expiration time is before 55 minutes

@Slf4j
@Component
public class RedisKeyExpirationListener extends KeyExpirationEventMessageListener {

public RedisKeyExpirationListener(RedisMessageListenerContainer listenerContainer) {
    super(listenerContainer);
}

public DateTimeFormatter dateTimeFormatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss");
@Autowired
private StringRedisTemplate stringRedisTemplate;

@Override
public void onMessage(Message message, byte[] pattern) {
    String keyName = new String(message.getBody());
    LocalDateTime parse = LocalDateTime.parse(keyName.split("@")[1], dateTimeFormatter);
    long seconds = Duration.between(parse, LocalDateTime.now()).getSeconds();
    stringRedisTemplate.execute((RedisCallback<Object>) connection -> {
        Long size = connection.dbSize();
        log.info("be overdue key:" + keyName + " ,current size:" + size + " ,Lag time" + seconds);
        return null;
    });
}

}

Here is the current dbSize and latency of printing after expiration is detected

@Bean
public RedisMessageListenerContainer configRedisMessageListenerContainer(RedisConnectionFactory connectionFactory) {

ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
executor.setCorePoolSize(100);
executor.setMaxPoolSize(100);
executor.setQueueCapacity(100);
executor.setKeepAliveSeconds(3600);
executor.setThreadNamePrefix("redis");
// Reflection policy: how to handle new tasks when the pool has reached max size
// Call_runs: the task is not executed in the new thread, but is executed by the thread of the caller
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
executor.initialize();
RedisMessageListenerContainer container = new RedisMessageListenerContainer();
// Set up Redis's connection factory
container.setConnectionFactory(connectionFactory);
// Set thread pool for listening
container.setTaskExecutor(executor);
// Set listening Topic
return container;

}

Set the expiration monitoring and thread pool information of Redis. The final test result is that when the number of keys is less than 10000, the expiration notification can be completed within 10s. However, if the number reaches 30000, some keys will be delayed 120s. By the way, post my latest log

2020-05-13 22:16:48.383: overdue key:2020-05-13 11:56:02@2020-05-13 22:14:08, current size:57405, lag time: 160
2020-05-13 22:16:49.389: overdue key:2020-05-13 11:56:02@2020-05-13 22:14:32, current size:57404, lag time: 137
2020-05-13 22:16:49.591: overdue key:2020-05-13 10:56:02@2020-05-13 22:13:20, current size:57403, lag time: 209
2020-05-13 22:16:50.093: expired key:2020-05-13 20:56:00@2020-05-13 22:12:32, current size:57402, lag time 258
2020-05-13 22:16:50.596: overdue key:2020-05-13 07:56:03@2020-05-13 22:13:28, current size:57401, lag time: 202
2020-05-13 22:16:50.697: overdue key:2020-05-13 20:56:00@2020-05-13 22:14:32, current size:57400, lag time 138
2020-05-13 22:16:50.999: overdue key:2020-05-13 19:56:00@2020-05-13 22:13:44, current size:57399, lag time 186
2020-05-13 22:16:51.199: expired key:2020-05-13 20:56:00@2020-05-13 22:14:40, current size:57398, lag time 131
2020-05-13 22:16:52.205: overdue key:2020-05-13 15:56:01@2020-05-13 22:16:24, current size:57397, lag time: 28
2020-05-13 22:16:52.808: overdue key:2020-05-13 06:56:03@2020-05-13 22:15:04, current size:57396, lag time: 108
2020-05-13 22:16:53.009: overdue key:2020-05-13 06:56:03@2020-05-13 22:16:40, current size:57395, lag time: 13
2020-05-13 22:16:53.110: overdue key:2020-05-13 20:56:00@2020-05-13 22:14:56, current size:57394, lag time 117
2020-05-13 22:16:53.211: overdue key:2020-05-13 06:56:03@2020-05-13 22:13:44, current size:57393, lag time 189
2020-05-13 22:16:53.613: overdue key:2020-05-13 15:56:01@2020-05-13 22:12:24, current size:57392, lag time 269
2020-05-13 22:16:54.317: overdue key:2020-05-13 15:56:01@2020-05-13 22:16:00, current size:57391, lag time 54
2020-05-13 22:16:54.517: overdue key:2020-05-13 18:56:00@2020-05-13 22:15:44, current size:57390, lag time: 70
2020-05-13 22:16:54.618: expired key:2020-05-13 21:56:00@2020-05-13 22:14:24, current size:57389, lag time 150
2020-05-13 22:16:54.819: overdue key:2020-05-13 17:56:00@2020-05-13 22:14:40, current size:57388, lag time: 134
2020-05-13 22:16:55.322: overdue key:2020-05-13 10:56:02@2020-05-13 22:13:52, current size:57387, lag time 183
2020-05-13 22:16:55.423: overdue key:2020-05-13 07:56:03@2020-05-13 22:14:16, current size:57386, lag time 159

It can be seen that when the number reaches 50000, most of them have been delayed for two minutes, which is totally unbearable for the business side.

summary

Maybe here, you will say that Redis dug a big hole for you, but in fact, these are clearly written on the document.

Especially in Timing of expired events, it is clearly stated that "basically expired events are generated when the Redis server deletes the key and not when the time to live potentially reaches the value of zero." after reading these two articles, you will feel that Redis's expiration strategy is also quite 'Low'.

Original release time: May 13, 2020
Author: dike
This article comes from:“ Nuggets ”For more information, you can focus on "gold diggers"