Guava caching refreshAfterWrite confusion

Question

I'm getting results that I don't really understand while using Guava Caches.

I am implementing a single key cache that I want to refresh asynchronously.

I hit the cache every second and I have set refreshAfterWrite to 20 seconds. My load/reload function takes 5 seconds.

If I print out at the start of the load/reload method the current time - I would expect some results like this:

load call started at 00:00:00
reload call started at 00:00:25
reload call started at 00:00:50

So the load would take 5 seconds and the next write would trigger 20 seconds after that (5+20=25). That write would occur at 50 seconds (25 + 5 + 20 = 50) seconds after that.. etc

Instead I get:

load call started at 00:00:00
reload call started at 00:00:25
reload call started at 00:00:30

This suggests that the second reload occurs straight after the first reload has finished processing.

I thought that the write would occur after the future has been processed and so the next reload would be scheduled for 20 seconds after that?

Have I found a bug or do I have a fundamental misunderstanding of how refreshAfterWrite works?

Sample code is below:

private static SimpleDateFormat format = new SimpleDateFormat("hh:mm:ss");

    public static void main(String[] args) throws ExecutionException, InterruptedException {

        final ExecutorService executor = Executors.newFixedThreadPool(3);

        final LoadingCache<String, Long> cache = CacheBuilder.newBuilder().maximumSize(1) //
                .refreshAfterWrite(20, TimeUnit.SECONDS)//
                .build(new CacheLoader<String, Long>() {//
                    public Long load(String key) {
                        return getLongRunningProcess("load", key);
                    }

                    public ListenableFuture<Long> reload(final String key, Long prevGraph) {
                        ListenableFutureTask<Long> task = ListenableFutureTask.create(new Callable<Long>() {
                            public Long call() {
                                return getLongRunningProcess("reload", key);
                            }
                        });
                        executor.execute(task);
                        return task;
                    }
                });

        while (true) {
            Thread.sleep(1000L);
            cache.get(CACHE_KEY);
        }
    }

    private static Long getLongRunningProcess(String callType, String key) {
        System.out.printf("%s call started at %s\n", callType, format.format(new Date()));
        try {
            Thread.sleep(5000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return counter.getAndIncrement();
    }

}

Answer 1

I think you've found a legit bug. (I help maintain common.cache.)

If I'm following things correctly, I believe the chain of events is as follows:

Let's say get A is the first get that causes a refresh, and get B is the first get after that.

• Get A calls scheduleRefresh, which starts the refresh task in the executor. The entry value reference is replaced with a LoadingValueReference, and loadAsync adds a listener waiting for the reload to complete.
• The forked task for the Get A reload completes and acquires the lock.
• Get B calls scheduleRefresh. The access time has not been updated yet, so it proceeds, and goes into insertLoadingValueReference.
• The forked task for the Get A reload updates the write time, and replaces the value reference with a StrongValueReference, since the load is complete. The lock is released.
• Get B determines that the value isn't still in the process of loading, so it proceeds to start up a new reload.

(Update: filed https://code.google.com/p/guava-libraries/issues/detail?id=1211.)