An issue in with Timeouts / Response Listener

[rickilambert]

Hi All - Sorry for what is likely to be a bit of a ramble but I will try my best to explain the issue I had yesterday as clearly as possible

So - I have been using Caffeine cache (2.9.3) to create an application that expires some keys (and their associated values) when the key has not been updated within a certain window (1 minute)

My code for this looks roughly as follows

private final Cache<String, LocalDateTime> cache = Caffeine.newBuilder()
            .executor(Runnable::run)
            .scheduler(forScheduledExecutorService(newSingleThreadScheduledExecutor()))
            .removalListener((key, value, cause) -> removalListener((String) key, (LocalDateTime) value, cause))
            .expireAfter(new MyExpiry())
            .weakKeys()
            .weakValues()
            .build();

private void removalListener(String key, LocalDateTime value, RemovalCause cause) {

    if (cause == RemovalCause.EXPIRED) {
        System.out.println("key evicted " + key + " value was " + value) ;
        //do some stuff
    }
}

public boolean addToCache() {
    //Do some checking
    System.out.println("adding to cache");
    cache.put("some key", someValue);
    return true;
}

public class MyExpiry implements Expiry {

    private final long expiry = Duration.ofSeconds(60).toNanos();

    @Override
    public long expireAfterCreate(@NonNull Object o, @NonNull Object o2, long l) {
        return expiry;

    }

    @Override
    public long expireAfterUpdate(@NonNull Object o, @NonNull Object o2, long l, @NonNegative long l1) {
        return expiry;
    }

    @Override
    public long expireAfterRead(@NonNull Object o, @NonNull Object o2, long l, @NonNegative long l1) {
        return l1;
    }
}

This has been working perfectly in test and production when only one producer is present. Yesterday, unfortunately we had a scenario where we had 2 producers so updates occurred a little more frequently (all be it marginally so i am not sure if this is the actual cause)

To note below - when I say 19 different key value pairs - it is always the same keys, just different value objects (these value objects have created time hence I know how to link the timeout occurrence to the insert)

The timing of events went like this;

1. At 14:17:14 I received an update with 19 different key value pairs - all added to the cache according to my logs
2. At 14:17:16 I received an update with 19 different key value pairs - all added to the cache according to my logs
3. At 14:17:35 I received an update with 19 different key value pairs - all added to the cache according to my logs
4. At 14:17:54 I received an update with 19 different key value pairs - all added to the cache according to my logs
5. At 14:18:13 I received an update with 19 different key value pairs - all added to the cache according to my logs
6. At 14:18:14 I received a Timeout for all of the instruments from step 1)
7. Some point after here the second publisher dropped off and normal flow resumed for the rest of the day

I really am not sure why the behaviour did this but here are some initial thoughts / questions I have and maybe someone maybe able to tell me where I am wrong / offer some advise please?

• It seems as though any update to the cache after step 1 made no effect on the remaining Time To Live - could this be due to the updates 1 and 2 being so close together that some blocking occurred?
• I only log prior to adding to the cache as opposed to after - would logging after show if any blocking was occurring?
• I assume that between step 5 and 6 - the timeout in step 6 had already come in to place before the update had chance to take effect and my listener code just had not been invoked yet, thus this is just a timing issue as shown in the logs. Would a read write lock be useful here for the contention between put and removalListener?
• Would it be better to use an evictionListener as opposed to a removalListener - I must admit I have read the docs but am still struggling with my understanding

Anyway - sorry for the long ramble and thank you very much for reading - I hope it made sense! I am trying my best to reproduce this behaviour but am unable to :(

Kind regards

[ben-manes]

Thanks for trying to explain the problem.

I have been using Caffeine cache (2.9.3)

If possible then I'd recommend using 3.x. Java 8 itself reached end-of-life for active support over a year ago, with on-going support for security fixes until 2030. Similarly this project supports 2.x releases, but does not actively backport or make fixes unless impacting a 2.x user. Thus, 2.x is not actively developed and there is always a chance that 3.x contains a fix that would have avoided your problems.

an application that expires some keys (and their associated values) when the key has not been updated within a certain window (1 minute)

In your case of a fixed duration of 1 minute for create or update, this matches expireAfterWrite. That feature came before Expiry as O(1) time for a variable TTL was a more difficult problem, so the implementations differ. If redone then I'd make expireAfterWrite a convenience function for expireAfter(expiry), as I think the newer design is better. All that is to say that maybe the implementation of expireAfterWrite won't run into your problem so you could give that a shot.

It seems as though any update to the cache after step 1 made no effect on the remaining Time To Live - could this be due to the updates 1 and 2 being so close together that some blocking occurred?

Could you show how you added to the cache? For example cache.put(k, v) would be an update to an existing mapping, whereas cache.get(k, k -> v) would be a read as the mapping exists (computeIfAbsent).

I only log prior to adding to the cache as opposed to after - would logging after show if any blocking was occurring?

Yes, that could occur if you have expensive functions that run to compute the value or on eviction. ConcurrentHashMap stores entries in a hashbin which is locked for writes, so hash collisions can result in longer block times. It doesn't sound like you expect to do that, but couldn't hurt to measure.

I assume that between step 5 and 6 - the timeout in step 6 had already come in to place before the update had chance to take effect and my listener code just had not been invoked yet, thus this is just a timing issue as shown in the logs. Would a read write lock be useful here for the contention between put and removalListener?

The cache tries to behave in a linearizable manner, so it is hard to tell. If the expiration lost a race with the update then the eviction would attempt would fail as it detected that the entry was no longer eligible and the listener would not be invoked. Once the removal listener is called the entry was already discarded from the mapping, so 5-6 look like they are in-order.

Would it be better to use an evictionListener as opposed to a removalListener - I must admit I have read the docs but am still struggling with my understanding

The removal listener is called asynchronously after the map operation completed, which means it does not block other cache operations but could be run out-of-order with other updates. The eviction listener is called synchronously within map's compute method that is discarding the entry, so it is blocking and receives change in key order. Ideally neither should write back to the cache, but the removal listener could do so safely while the eviction listener would violate the map contract. That distinction can be useful if trying to synchronize with some secondary state where out-of-order operations would cause mayhem.

[rickilambert]

Hi Ben - Thanks for the response

I cannot change the java version annoyingly so am stuck with the most recent 2.x release versions - which is a pity I must admit.

The reason I moved away from the expireAfterWrite approach was the introduction of the HashedTimingWheel in the expireAfter - which i thought would be a safer bet for when i get many writes in quick succession (I was trying to be pre-emptive) but maybe it is worth me switching back to test this approach again as for now it is unlikely to get updates <1 second apart.

My cache insertion is essentially just a cache.put<k,v> so this should just act as a replace I believe?

There is a possibility that the code in my removalListener is actually causing some issues - potentially with some slightly longer running process than what would be considered ideal. I wonder if it would be better to take the output of the removal listener and parse this in to a linked blocking queue for a scheduled executor to churn through the data because i am not overly bothered about the completion time of this request (within reason!) - so long as it is actually completed. It could well be this that caused the issue where update 1 and 2 came in in such quick succession - potentially meaning subsequent updates were missed. I am trying to recreate this locally as we speak but it is a real pain to do :)

Would increasing from a newSingleThreadScheduledExecutor to maybe an executor with a bigger pool help potentially?

I must admit - I am having a lot of fun playing around with Caffeine! I just need to properly learn the way it works - so apologies for the multitude of questions.

Kind regards

Ricki

[ben-manes]

maybe it is worth me switching back to test this approach again as for now it is unlikely to get updates <1 second apart.

Oh right. I'm planning on updating that logic to get around that quirk causing the reordering issue. Instead I was thinking of dropping updates to the timestamp within that 1s threshold, so at worst the cache expires the entry a little early. That's probably how I should have done it originally.

My cache insertion is essentially just a cache.put<k,v> so this should just act as a replace I believe?

Yes, that makes it very strange. Can you use asMap().put so that you can log if an insert or update?

Would increasing from a newSingleThreadScheduledExecutor to maybe an executor with a bigger pool help potentially?

Not for the scheduler, since each cache only schedules one task for expiration. If you switched the executor(Runnable::run) to a thread pool then multiple removal listener calls would be run async.

I must admit - I am having a lot of fun playing around with Caffeine! I just need to properly learn the way it works - so apologies for the multitude of questions.

haha, it is fun! I'm happy to answer questions and hope we can figure it out.