refreshAfterWrite returns stale value forever with long load times

[panghy]

We have observed that Caffeine may be stuck in a state where it constantly returns the old value if the loading time of a value is longer than the refreshAfterWrite time. We ran this in 2.4.0.

The following code demonstrates the issue:

 public static void main(String[] args) throws InterruptedException {
    AtomicInteger atomicInteger = new AtomicInteger(1);
    LoadingCache<String, Integer> cache = Caffeine.newBuilder().
        refreshAfterWrite(1, TimeUnit.SECONDS).build(new CacheLoader<String, Integer>() {
      @CheckForNull
      @Override
      public Integer load(@Nonnull String s) throws Exception {
        log.info("calling load");
        long sleepMs = (long) (Math.random() * 10000) + 5000;
        log.info("sleep for: " + sleepMs);
        Thread.sleep(sleepMs);
        log.info("slept for: " + sleepMs);
        int toReturn = atomicInteger.incrementAndGet();
        log.info("returning: " + toReturn);
        return toReturn;
      }
    });
    while (true) {
      int result = cache.get("hello");
      if (atomicInteger.get() != result) {
        log.info("got: " + result + " from cache but atomic integer is: " + atomicInteger.get());
      }
    }
  }

The output suggests that cache.get("hello") returns the value of 2 where as the atomic integer is returning a value much higher than that. In fact, after running for a long time, cache.get("hello") continues to return a value of 2 whereas the atomic integer has been incremented to the thousands.

Aug 03, 2017 6:17:49 PM queryserver.TestCaffeine main
INFO: got: 2 from cache but atomic integer is: 12983

[ben-manes]

Can you also try with an AsyncLoadingCache? For some reason I have the code,

long refreshWriteTime = isAsync ? (now + Async.MAXIMUM_EXPIRY) : now;

in refreshIfNeeded and I can't recall why they differ. It may be that both should simply be pushed forward to not be constrained by the refresh vs loading time.

You can use the synchronous() view to minimize the code change.

[panghy]

Indeed that seems to work:

public static void main(String[] args) throws InterruptedException, ExecutionException {
    AtomicInteger atomicInteger = new AtomicInteger(1);
    AsyncLoadingCache<String, Integer> cache = Caffeine.newBuilder().
        refreshAfterWrite(1, TimeUnit.SECONDS).buildAsync(new CacheLoader<String, Integer>() {
      @CheckForNull
      @Override
      public Integer load(@Nonnull String s) throws Exception {
        log.info("calling load");
        long sleepMs = (long) (Math.random() * 10000) + 5000;
        log.info("sleep for: " + sleepMs);
        Thread.sleep(sleepMs);
        log.info("slept for: " + sleepMs);
        int toReturn = atomicInteger.incrementAndGet();
        log.info("returning: " + toReturn);
        return toReturn;
      }
    });
    int matched = 0;
    while (true) {
      int result = cache.get("hello").get();
      if (atomicInteger.get() != result) {
        log.info("got: " + result + " from cache but atomic integer is: " + atomicInteger.get());
      } else {
        matched++;
        if (matched % 10000000 == 0) log.info("matched: " + matched +
            " current: " + atomicInteger.get());
      }
    }
  }

Updated to make sure that load is still being called (it is).

[ben-manes]

Okay. So I think what is happening is that when a refresh is needed, it CASes to the new write time to avoid a stampede of multiple. Then when the refresh completes it sets to the new value if the write timestamp matches. That way if you refresh but then insert, it won't stampede your insert and drop the refresh instead as likely a stale db read. Here it gets stuck because each new refresh being triggered causes the timestamp to increase, so the previous are dropped and the oldest value is kept until the last refresh completes. The async version is so far into the future that it won't hit that problem.

All of this is because we don't have a place to stash the Future. In Guava the hash table entry is subclassed with a special version for loading. That way the extra field(s) are only on the computing entry rather than on every single one. Caffeine doesn't fork the hash table so we can't do that, meaning I hacked the writeTime to get a similar effect.

It sounds like the resolution is to make it work like Async, add a unit test, and get a release out. I'll try to do that tonight if possible.

[panghy]

Makes sense, thanks so much!

[panghy]

Thanks @ben-manes, any chance we could get a release soon?

[ben-manes]

Yeah, just stealing time on the train and work trying to wrap it up. I'll release today when I get a chance.

[ben-manes]

Released. It may take up to 2 hours for Maven Central to sync with staging.

Thanks for the bug report and sorry for any frustrations this caused.

[panghy]

No, thank you for the quick turn around!