Unexpected excess replacement when using per-item expiry with or_try_insert_with

[wez]

First I apologize that I don't have this reduced to a self-contained test case--it's part of a larger more complex setup.

The background is that I have a cache configured to use LRU policy (LFU disabled, because I initially suspected LFU as the cause of the behavior described below).

I have an eviction listener enabled that prints out the evictions
This particular cache has a capacity of 1; the key in this scenario consists of an epoch counter and a constant string. The epoch counter rarely changes, and doesn't need to change for the bad part of the scenario to trigger, but the change can sometimes encourage it to happen, but it is still intermittent.

My Expiry impl looks like this, to enable per-item TTLs. For this particular cache, the TTL is 1 minute in duration.

/// this is the value type stored in the cache
#[derive(Debug, Clone)]
struct Item<V>
where
    V: Send,
    V: Sync,
{
    item: V,
    expiration: Instant,
}

struct PerItemExpiry<K, V> {
    marker: PhantomData<(K, V)>,
}

impl<K: Send, V: Send + Sync> Expiry<K, Item<V>> for PerItemExpiry<K, V> {
    fn expire_after_create(
        &self,
        _key: &K,
        item: &Item<V>,
        created_at: Instant,
    ) -> Option<Duration> {
        Some(item.expiration - created_at)
    }
}

let cache = Cache::builder()
    .name(&name)
    .eviction_policy(EvictionPolicy::lru())
    .eviction_listener({
        let name = name.clone();
        move |k, _v, reason| {
            tracing::info!("evicting {name} {k:?} {reason:?}");
        }
    })
    .max_capacity(capacity) // capacity is 1 in this scenario
    .expire_after(PerItemExpiry {
        marker: PhantomData,
    })
    .build();

My insertion logic looks like this:

let entry = self
    .inner
    .cache
    .entry_by_ref(name)
    .or_try_insert_with(async move {
        tracing::info!("populate"); // responsible for logging the lines in the output below
        let item = fut.await?;
        Ok(Item {
            item,
            expiration: Instant::now() + ttl, // ttl is 1 minute for this scenario
        })
    })
    .await?;

The mechanics generally work fine; populate is never executed concurrently, expiry works at the expected time, and I'll see logs like this around an eviction and re-population:

2025-03-02T16:01:03.012510Z  INFO qmaint-5 lruttl: evicting Expired
2025-03-02T16:01:03.012985Z  INFO qmaint-5 mod_memoize: populate

but the issue is that sometimes I see a run of logs like this; in reality I'm logging the keys here but I've omitted them from here for privacy reasons. For this run, each of these log lines references the same key. The qmaint-X portion of the log line is the thread identifier; you can see that multiple threads are at work here:

2025-03-02T16:00:02.624104Z  INFO qmaint-0 mod_memoize: populate
2025-03-02T16:00:02.636251Z  INFO qmaint-0 lruttl: evicting Replaced
2025-03-02T16:00:02.644892Z  INFO qmaint-7 mod_memoize: populate
2025-03-02T16:00:02.655786Z  INFO qmaint-0 lruttl: evicting Replaced
2025-03-02T16:00:02.662516Z  INFO qmaint-0 mod_memoize: populate
2025-03-02T16:00:02.674000Z  INFO qmaint-6 lruttl: evicting Replaced
2025-03-02T16:00:02.681391Z  INFO qmaint-0 mod_memoize: populate
2025-03-02T16:00:02.692567Z  INFO qmaint-7 lruttl: evicting Replaced
2025-03-02T16:00:02.705875Z  INFO qmaint-7 mod_memoize: populate
2025-03-02T16:00:02.716634Z  INFO qmaint-6 lruttl: evicting Replaced
2025-03-02T16:00:02.730401Z  INFO qmaint-0 mod_memoize: populate
2025-03-02T16:00:02.740834Z  INFO qmaint-7 lruttl: evicting Replaced
2025-03-02T16:00:02.762006Z  INFO qmaint-7 mod_memoize: populate
2025-03-02T16:00:02.772746Z  INFO qmaint-6 lruttl: evicting Replaced
2025-03-02T16:00:02.779289Z  INFO qmaint-6 mod_memoize: populate
2025-03-02T16:00:02.789184Z  INFO qmaint-0 lruttl: evicting Replaced
2025-03-02T16:00:02.796037Z  INFO qmaint-5 mod_memoize: populate
2025-03-02T16:00:02.807161Z  INFO qmaint-0 lruttl: evicting Replaced
2025-03-02T16:00:02.814024Z  INFO qmaint-0 mod_memoize: populate
2025-03-02T16:00:02.824656Z  INFO qmaint-6 lruttl: evicting Replaced
2025-03-02T16:00:02.831145Z  INFO qmaint-6 mod_memoize: populate
2025-03-02T16:00:02.841511Z  INFO qmaint-7 lruttl: evicting Replaced
2025-03-02T16:00:02.851936Z  INFO qmaint-7 lruttl: evicting Expired
2025-03-02T16:00:02.851956Z  INFO qmaint-7 mod_memoize: populate

There is a sequence of populate lines occurring in quick succession within the span of the 1 minute TTL. This is highly undesirable because the latency outliers for this particular populate function can be multiple seconds in the very worst case--that's the motivating factor for using a cache!

In the cases where I've observed this, there is typically a run of Replace/populate that terminates in Expired/populate, but sometimes it can continue for a long time.

This feels like an edge case around processing the per-item TTL and I'm not sure if there an obvious gotcha that I should be aware of to handle this in my code. That Replaced is being logged as an eviction reason is a bit surprising because my logic doesn't explicitly unconditionally insert a value, and that makes me wonder whether there is an edge case where an item doesn't have its TTL updated when the init future is evaluated by or_try_insert_with?

What do you suggest I dig into here?

Thanks!