Caffeine: Fix ExpirationDelay calculation

[YuryAndr]

Hello. Please, consider the following issue.

Problem

• ExpirationDelay varies within the range up to configured expiration duration multiplied by 3

Steps to reproduce (worst case):

• configure Cache with expireAfterWrite and async removalListener
• write the first entry to Cache
• wait a few milliseconds
• write the second entry to Cache
• wait for expiration

Expected

• both entries are expired after the configured expiration duration

Actual

• the first entry is expired after the configured expiration duration
• the second entry is expired after a period which is 3 times greater than the configured expiration duration

Example
There is Kotlin Unit test

    companion object {
        const val EXPIRATION_PERIOD = 10L
        const val MAX_EXPIRATION_PERIOD = 13L
        const val FIRST_ENTRY_KEY = 1
        const val SECOND_ENTRY_KEY = 2
    }

    @Test
    fun expiration() {
        //given
        val countDownLatch = CountDownLatch(2)
        val actualExpirationPeriods: MutableMap<Int, Long> = mutableMapOf()

        val cache = Caffeine.newBuilder()
                .expireAfterWrite(EXPIRATION_PERIOD, TimeUnit.SECONDS)
                .scheduler(Scheduler.forScheduledExecutorService(
                        Executors.newScheduledThreadPool(5)))
                .removalListener { key: Any?, value: Any?, _: RemovalCause? ->
                    val expirationPeriod = (System.currentTimeMillis() - (value as Long)) / 1000
                    println("Key $key expired after $expirationPeriod seconds")
                    actualExpirationPeriods[key as Int] = expirationPeriod
                    countDownLatch.countDown()
                }
                .build<Int, Long> { System.currentTimeMillis() }

        //when

        //add first entry
        cache[FIRST_ENTRY_KEY]

        Thread.sleep(10)

        //add second entry
        cache[SECOND_ENTRY_KEY]

        countDownLatch.await(40, TimeUnit.SECONDS)

        //then
        assertTrue(actualExpirationPeriods[FIRST_ENTRY_KEY]!! < MAX_EXPIRATION_PERIOD, "Too long ExpirationPeriod for first entry")
        assertTrue(actualExpirationPeriods[SECOND_ENTRY_KEY]!! < MAX_EXPIRATION_PERIOD, "Too long ExpirationPeriod for second entry")
    }

The second entry is expired after about 30 seconds instead of 10.

Possible solution

There is a formula at BoundedLocalCache::868

Node<K, V> node = writeOrderDeque().peekFirst();
if (node != null) {
  delay = Math.min(delay, now - node.getWriteTime() + expiresAfterWriteNanos());
}

This expression might be replaced with

expiresAfterWriteNanos() - (now - node.getWriteTime())

Because after handling expiration of the first entry the current code calculates next expiration delay as
period after write + expiration duration
And period after write equals to the expiration duration at the moment of calculation.

So the second entry remains in cache for 3 expiration durations in worst case.

Will be happy for your feedback.
Thank you!

[ben-manes]

Thanks! I'll take a look over the weekend and offhand it does sound like I screwed up that calculation.

[ben-manes]

I converted your test case to use mockito so that I can bundle it in the test suite without the large sleeps. That seems to reproduce the same issue, so I'll refactor it a bit to integrate into our @CacheSpec scaffolding and get the fix ready soon.

public final class Issue431Test {
  private static final int FIRST_ENTRY_KEY = 1;
  private static final int SECOND_ENTRY_KEY = 2;
  private static final Duration DELAY_TO_NEXT_KEY = Duration.ofMillis(10);
  private static final Duration EXPIRATION_PERIOD = Duration.ofSeconds(10);
  private static final Duration MAX_EXPIRATION_PERIOD = Duration.ofSeconds(13);

  @Test
  public void expiration() throws InterruptedException {
    FakeTicker ticker = new FakeTicker();
    Scheduler scheduler = Mockito.mock(Scheduler.class);
    Map<Integer, Duration> actualExpirationPeriods = new HashMap<>();
    ArgumentCaptor<Long> delay = ArgumentCaptor.forClass(long.class);
    ArgumentCaptor<Runnable> task = ArgumentCaptor.forClass(Runnable.class);
    when(scheduler.schedule(any(), task.capture(), delay.capture(), any()))
        .thenReturn(Futures.immediateFuture(null));

    LoadingCache<Integer, Duration> cache = Caffeine.newBuilder()
        .ticker(ticker::read)
        .scheduler(scheduler)
        .executor(Runnable::run)
        .expireAfterAccess(EXPIRATION_PERIOD)
        .removalListener((Integer key, Duration value, RemovalCause cause) -> {
          Duration expirationPeriod = Duration.ofNanos(ticker.read()).minus(value);
          System.out.printf("Key %s expired after %s seconds%n", key,
              TimeUnit.MILLISECONDS.toSeconds(expirationPeriod.toMillis()));
          actualExpirationPeriods.put(key, expirationPeriod);
        }).build(key -> Duration.ofNanos(ticker.read()));

    cache.get(FIRST_ENTRY_KEY);
    ticker.advance(DELAY_TO_NEXT_KEY);
    cache.get(SECOND_ENTRY_KEY);

    Duration expireFirstKey = Duration.ofNanos(delay.getValue()).minus(DELAY_TO_NEXT_KEY);
    ticker.advance(expireFirstKey);
    task.getValue().run();

    Duration expireSecondKey = Duration.ofNanos(delay.getValue());
    ticker.advance(expireSecondKey);
    task.getValue().run();

    System.out.printf("Delays (ms): %,d, %,d%n",
        expireFirstKey.toMillis(), expireSecondKey.toMillis());

    assertThat("Too long ExpirationPeriod for first entry",
        actualExpirationPeriods.get(FIRST_ENTRY_KEY), lessThan(MAX_EXPIRATION_PERIOD));
    assertThat("Too long ExpirationPeriod for second entry",
        actualExpirationPeriods.get(SECOND_ENTRY_KEY), lessThan(MAX_EXPIRATION_PERIOD));
  }
}

[ben-manes]

Released 2.8.5. Thank you for investigating this issue, supplying a test, and the fix!

[YuryAndr]

Great, thank you!