Unexpected cache misses with expireAfterWrite using multiple keys

[ybayk]

We just discovered that while observing a lot of cache misses in our logs.
I isolated the problem down to simple unit test. However, it is intermittent, and is not reproducible if is run under gradle testing. So I put multiple attempts inside a loop and also recommend using built-in Eclipse tester to reproduce that. I am also able to reproduce as a simple app with main() on Linux and Mac.

The unit tests are provided below. There are two scenarios. One test that uses only one cache key works fine, another test that uses the same logic but with two keys fails on unexpected cache miss.

package com.thomsonreuters.onep.pito.utils;

import static org.junit.Assert.assertEquals;

import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.Executor;
import java.util.concurrent.TimeUnit;

import org.junit.Test;

import com.github.benmanes.caffeine.cache.AsyncLoadingCache;
import com.github.benmanes.caffeine.cache.CacheLoader;
import com.github.benmanes.caffeine.cache.Caffeine;

public class CaffeineTest {

  private static final int ATTEMPTS = 100;
  private static final int TTL = 100;
  private static final int EPSILON = 10;

  @Test
  public void testWithCoupleOfKeys() throws Exception {
    testExpiration(true);
  }

  @Test
  public void testSameWithSingleKey() throws Exception {
    testExpiration(false);
  }


  private void testExpiration(boolean withPairOfKey) throws Exception {
    final ConcurrentMap<String,String> source = new ConcurrentHashMap<>();
    final ConcurrentMap<String,Date> lastLoad = new ConcurrentHashMap<>();

    class Loader implements CacheLoader<String,String> {

      private void reportCacheMiss(String key) {
        Date now = new Date();
        Date last = lastLoad.get(key);
        System.out.print(new SimpleDateFormat("hh:MM:ss.SSS").format(new Date()) + ": cache miss for key: " + key);
        if (last != null) {
          System.out.println(" -  " + (now.getTime() - last.getTime()) + "ms after last load");
        } else {
          System.out.println();
        }
        lastLoad.put(key, now);
      }

      @Override
      public String load(String key) {
        reportCacheMiss(key);
        return source.get(key);
      }

      @Override
      public CompletableFuture<String> asyncLoad(String key, Executor executor) {
        reportCacheMiss(key);
        return CompletableFuture.completedFuture(source.get(key));
      }
    }    

    for (int i = 0; i < ATTEMPTS; i++) {
      System.out.println("Attempt #" + i);

      //initial value
      source.put("foo", "foo0");
      if (withPairOfKey) {
        source.put("bar", "bar0");
      }

      lastLoad.clear();
      AsyncLoadingCache<String,String> cache = Caffeine.newBuilder()
          .expireAfterWrite(TTL, TimeUnit.MILLISECONDS)
          .buildAsync(new Loader());

      assertEquals("should serve initial value", "foo0", cache.get("foo").get());
      if (withPairOfKey) {
        assertEquals("should serve initial value", "bar0", cache.get("bar").get());
      }

      //first update
      source.put("foo", "foo1");
      if (withPairOfKey) {
        source.put("bar", "bar1");
      }

      assertEquals("should serve cached initial value", "foo0", cache.get("foo").get());
      if (withPairOfKey) {
        assertEquals("should serve cached initial value", "bar0", cache.get("bar").get());
      }
      Thread.sleep(EPSILON); //sleep for less than expiration
      assertEquals("should still serve cached initial value", "foo0", cache.get("foo").get());
      if (withPairOfKey) {
        assertEquals("should still serve cached initial value", "bar0", cache.get("bar").get());
      }
      Thread.sleep(TTL + EPSILON); //sleep until expiration
      assertEquals("should now serve first updated value", "foo1", cache.get("foo").get());
      if (withPairOfKey) {
        assertEquals("should now serve first updated value", "bar1", cache.get("bar").get());
      }

      //second update
      source.put("foo", "foo2");
      if (withPairOfKey) {
        source.put("bar", "bar2");
      }

      assertEquals("should still serve cached first updated value", "foo1", cache.get("foo").get());
      if (withPairOfKey) {
        assertEquals("should still serve cached first updated value", "bar1", cache.get("bar").get());
      }
      Thread.sleep(EPSILON); //sleep for less than expiration
//it never fails here for the first key
      assertEquals("should still serve cached first updated value", "foo1", cache.get("foo").get());
      if (withPairOfKey) {
//it fails here after a few attempts because of cache miss
        assertEquals("should still serve cached first updated value", "bar1", cache.get("bar").get());
      }
    }
  }
}

[ben-manes]

Thanks. I won't be able to take a look at this until tonight.

Most of the unit tests use a Ticker to manipulate time. Can you verify that it fails with that, too? If not then it would indicate an unexpected visibility problem.

[ben-manes]

Oh, this is the async cache. Sorry, I need to play with the code to get a sense of what is going on. I just reproduced it failing and see it runs if I use a direct executor but fails on a single-thread executor. So definitely some race, but not sure what yet.

[ybayk]

Yes, that's async cache. Not sure how it behaves on a blocking cache as we do not use it.
Also whether the future is immediate or real one does not make any difference as we have the same issue with true futures.
So as far as I understood you do not need ticker based test anymore?

[ben-manes]

Nope, that was my misreading. Since it runs fine with a direct executor and fails with a single-threaded, its a race. I have to verify your code is valid because sleeping and waking are not exact time durations. The big question is whether the race is valid or not.

So my first step will be to strengthen the visibility to see if it passes. Right now reads and writes to the timestamp piggy back on other volatiles generating our memory barriers to avoid excessive cpu stalls.

[ben-manes]

I took a look and here's my current guess. I haven't been able to validate it yet, so hopefully I'm not too far off base and will have a patch released by the end of the weekend.

When a write to key1 occurs, it triggers a cache maintenance cycle (on the executor) to evict/expire/reorder entries in the policy's linked lists. The expiration check is racy, as key2 could have expired but then be resurrected by a concurrent update. The atomic removal (via computeIfPresent) doesn't validate that the entry is still expired, though it probably should. This race was assumed to be rare, so one or two extra evictions wouldn't be noticeable. That may have been a bad assumption if this happened often enough for you to investigate and write a test that triggered the race reliably.

I verified that the tests pass if the maintenance cycle is disabled. I haven't been able to get a hack that resolves the race to work reliably yet, which would let me then fix it properly. So I might either be tired or there is a different issue at play. Regardless I hope to figure it out, fix it, and have a release by the end of the weekend.

[ybayk]

Thank you for looking at it promptly. Yes, the issue seems to be common at least with our use case, where we deal with a few keys used side by side within a short period of time. We noticed it by observing our Cassandra queries being way too more frequent than expected, which immediately raised a question about cache layer not working properly.

[ben-manes]

I was exhausted last night and flipped a gt / lt sign which is why my quick hack of a fix didn't work. It was Yom Kippur and I was out late when we broke the fast.

So the above rational is correct. If I hack BoundedLocalCache#evictEntry to use the following your tests pass. I should be able to clean this up, wrap your code into an integration test, and have a release out in the timeframe I promised.

Thanks for doing the detective work to isolate the bug and report it.

data.computeIfPresent(node.getKeyReference(), (k, n) -> {
  if (actualCause == RemovalCause.EXPIRED) {
    long now = expirationTicker().read();
    if (expiresAfterWrite()) {
      long expirationTime = now - expiresAfterWriteNanos();
      if (n.getWriteTime() >= expirationTime) {
        resurrect[0] = true;
        return n;
      }
    }
  }
  if (n == node) {
    writer.delete(key, value, actualCause);
    removed[0] = true;
    return null;
  }
  return n;
});
if (resurrect[0]) {
  return;
}

[ben-manes]

I have the fix ready and refactored your tests a little. Because this relies on exact timings it can't run reliably as part of the build / CI yet. There is enough other work (concurrent tests, shared CI) that the timing thresholds can be exceeded. I'll fix this later by isolating the test in its own build step, though that will probably only run locally because the CI is too heavily loaded.

I'll get the next release put together tonight.