Distributed Redis cache configuration not obeying sliding window expiration update on access

[GMacAussie]

Hi there,

First, thank you for a great package!

We are experiencing an issue when using a distributed Redis configuration and a sliding window expiry, where accessing a key updates the sliding window only on the first access.

We are using this distributed Redis cache successfully for non-expiry, absolute expiry and sliding window when the cache key is regenerated on cache miss. This new use case uses the sliding window expiry as a gate (like a session cache).

Have we misunderstood the behaviour of a distributed Redis cache configuration with respect to sliding window expiration?

From the log, it appears that given the key is not in system cache, it will retrieve it from Redis with the sliding window update. The next access finds the key in system cache, and appears not to push the sliding window update(?). Note that the cache item itself has the expiration, not the cache configuration.

Here is our configuration:

ICacheManagerConfiguration CacheL1L2BP = new ConfigurationBuilder()
        //.WithUpdateMode(CacheUpdateMode.Up) // this has no effect
        .WithMicrosoftLogging((logger) => logger.AddProvider(new NLogLoggerProvider()))
        .WithSystemRuntimeCacheHandle("In-Process")
        .And
        .WithRedisConfiguration("Redis", redisConnection, enableKeyspaceNotifications: true)
        .WithJsonSerializer()
        .WithMaxRetries(4)
        .WithRetryTimeout(2000)
        .WithRedisBackplane("Redis")
        .WithRedisCacheHandle("Redis", true)
        .EnableStatistics()
        .Build();

Note that we suffix the ,allowAdmin=true (also tried ,useAdmin=true) to the connection string, but we still get the message:

Could not read configuration from redis to validate notify-keyspace-events. Most likely useAdmin is not set to true.

However we do see keyspace events (see log below). Our Redis cache is a Azure Redis Standard C0 with the notify-keyspace-events set to AKE.

This is the reproduction code (see attached solution):

// create a boolean gate cache
ICacheManager<bool> distribCache = CacheFactory.FromConfiguration<bool>("Distrib Test", CacheL1L2BP);

// add/update the key @ t0, expiry @ t0+60
Console.WriteLine($"Add Key 123 @ t0     -> {DateTime.UtcNow}={distribCache.AddOrUpdate(new CacheItem<bool>("123", true, ExpirationMode.Sliding, TimeSpan.FromSeconds(60)), v => true)}");

// next access @ t0+45
Thread.Sleep(45000);

// access @ t0+45, expiry @ t0+105, success
Console.WriteLine($"Get Key 123 @ t0+45  -> {DateTime.UtcNow}={distribCache.Get("123")}");

// next access @ t0+90
Thread.Sleep(45000);

// access @ t0+90, expiry @ t0+150, success
Console.WriteLine($"Get Key 123 @ t0+90  -> {DateTime.UtcNow}={distribCache.Get("123")}");

// next access @ t0+135
Thread.Sleep(45000);

// access @ t0+135, expiry @ t0+195, failure
Console.WriteLine($"Get Key 123 @ t0+135 -> {DateTime.UtcNow}={distribCache.Get("123")}");

Here is the NLog. I removed the cache startup preamble:

2021-02-13T17:46:55.3439844Z DEBUG LAPTOP-12345678 - CacheManager.Redis.RedisCacheHandle Could not read configuration from redis to validate notify-keyspace-events. Most likely useAdmin is not set to true. 
2021-02-13T17:46:55.6124058Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Add or update: 123 . 
2021-02-13T17:46:55.6124058Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Add ['123', exp:Sliding 00:01:00, lastAccess:2/13/2021 5:46:55 PM] started. 
2021-02-13T17:46:55.6313512Z INFO LAPTOP-12345678 - CacheManager.Redis.RedisCacheHandle Loading scripts. 
2021-02-13T17:46:55.9920906Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Evict [:123] from other handles excluding handle '1'. 
2021-02-13T17:46:55.9920906Z DEBUG LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Evicting ':123' from handle 'In-Process'. 
2021-02-13T17:46:55.9920906Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Notified backplane 'change' because ['123', exp:Sliding 00:01:00, lastAccess:2/13/2021 5:46:55 PM] was added. 
2021-02-13T17:46:55.9920906Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Add or update: 123 : successfully added the item. 
2021-02-13T17:46:56.0289973Z DEBUG LAPTOP-12345678 - CacheManager.Redis.RedisCacheBackplane Backplane is sending 1 messages (0 skipped). 
2021-02-13T17:47:41.1052721Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123] started. 
2021-02-13T17:47:41.1052721Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123], item NOT found in handle[0] 'In-Process'. 
2021-02-13T17:47:41.2129921Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123], found in handle[1] 'Redis'. 
2021-02-13T17:47:41.4124504Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Start updating handles with ['123', exp:Sliding 00:01:00, lastAccess:2/13/2021 5:47:41 PM]. 
2021-02-13T17:47:41.4144451Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Updating handles, added ['123', exp:Sliding 00:01:00, lastAccess:2/13/2021 5:47:41 PM] to handle 'In-Process'. 
2021-02-13T17:48:26.4782297Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123] started. 
2021-02-13T17:48:26.4782297Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123], found in handle[0] 'In-Process'. 
2021-02-13T17:48:26.4782297Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Start updating handles with ['123', exp:Sliding 00:01:00, lastAccess:2/13/2021 5:48:26 PM]. 
2021-02-13T17:48:41.5127934Z DEBUG LAPTOP-12345678 - CacheManager.Redis.RedisCacheHandle Got expired event for key ':123' 
2021-02-13T17:48:41.5127934Z DEBUG LAPTOP-12345678 - CacheManager.Redis.RedisCacheHandle 'Redis' triggered remove ':123' because 'Expired'. 
2021-02-13T17:48:41.5127934Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Cleaning handles above '1' because of remove event. 
2021-02-13T17:48:41.5247595Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Evict from handles above: 123 : above handle 1. 
2021-02-13T17:48:41.5247595Z DEBUG LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Evicting ':123' from handle 'In-Process'. 
2021-02-13T17:49:11.4953541Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123] started. 
2021-02-13T17:49:11.4953541Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123], item NOT found in handle[0] 'In-Process'. 
2021-02-13T17:49:11.5609279Z TRACE LAPTOP-12345678 - CacheManager.Core.BaseCacheManager Get [:123], item NOT found in handle[1] 'Redis'. 

Solution:

CacheSliding.zip

[MichaCo]

Hi @GMacAussie That is the expected behavior, if both cache layers have the same sliding expiration, it might never get refreshed. I'm usually using a shorter absolute-expiration in the first layer and longer sliding-expiration in the Redis layer.

If you still want to use the same cache expiration in both layers because you cannot configure them separately or want to use the per key expiration, you can "update" the sliding window in both layers by calling .Expire, which will do a Get and then effectively a Put in both layers.

This operation is rather inefficient performance wise if you call that on every GET operation. Expire has to get the full data of the key, and then sends it to Redis to update the sliding windows. If you do that on every GET, you loose a lot of performance benefits of a 2 layered cache.

I highly recommend not to do that on every GET But there are solutions for this which would work, you need a small time window in which the Expire call would be skipped, but you'd have to make sure that the next call outside that window or the last call within the window would trigger an Expire; otherwise you could miss one call. That concept is called debouncing.

Unfortunately, it is nontrivial to implement debouncing properly and also very dependent on a use-case (needs configuration again at least). That's why this library doesn't handle stuff like that yet.

[GMacAussie]

Thanks for the reply @MichaCo.

Debouncing sounds a bit fraught, and at the end of the day it just might be easier (and more reliable?) to use Redis as a single cache layer.

Thanks for again for your reply.