refactor: make LocalCache not use synchronized to detect recursive loads (#6845)

[cortlepp]

This PR refactors LocalCache to no longer use synchronized in order to detect recursive loads and fail fast instead of deadlocking. The main motivation for this change is to make LocalCache work gracefully with JDK21 VirtualThreads when using a blocking operation inside a loader.

The new implementation saves the current Thread when creating a LoadingValueReference and checks it before waiting for the entry. Since the LoadingValueReference is swapped out eventually for the real entry, the refernce to the Thread exists only temporarily.

I also added some tests for the recursive load scenario, both for the direct load and if it occurs with a proxy loader in between.

Closes #6845.

[google-cla]

Thanks for your pull request! It looks like this may be your first contribution to a Google open source project. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

View this failed invocation of the CLA check for more information.

For the most up to date status, view the checks section at the bottom of the pull request.

[cpovirk]

(Thanks. We do need a signed CLA before we can look at this. The link above has some instructions.)

[cortlepp]

(Thanks. We do need a signed CLA before we can look at this. The link above has some instructions.)

Yeah, I'm working on it. I need a corporate CLA and am still figuring out from whom to get one at my company ^^.

[cortlepp]

@cpovirk sorry it took a while, but the CLA has been signed now, so we can continue with everything else now I think.

[cpovirk]

Thanks for putting this together!

Would it make sense to check the valueReference instead of e.getValueReference()? I ask because I discovered during testing that the current code has a race: It checks e.getValueReference() instanceof LoadingValueReference, and then it casts e.getValueReference() to LoadingValueReference, but the first e.getValueReference() call might return a loading reference and the second a completed reference.

One way to fix that is to call e.getValueReference() only once (e.g., checkRecursiveLoad(key, e.getValueReference());). But it would seem easier and less fragile to use valueReference if that's correct.

The worst thing that I can think of about using valueReference is that we might check the loading thread unnecessarily (in the case that the reference completed between our earlier isLoading() check and this one). But that doesn't seem like a significant worry.

It actually looks like we could change waitForLoadingValue to require a LoadingValueReference instead of a plain ValueReference: The code already checks this above, so we could just perform a cast before the call instead of a conditional cast here.

I have pretty well talked myself into trying this :) I'll report back the results. But please do speak up if I'm missing anything!

[cpovirk]

Concretely: https://github.com/google/guava/pull/6857/files#diff-98cf5b8d5ed981e94f4c745137a9b4ac3d0e896d0471cfb4e3baf85928c5053d

[cortlepp]

No your right I think (and the race could have definitely become a problem, good catch!). Just getting the ValueReference directly and not from the entry also seems much more straightforward in general, I think I must have overlooked that it's already present as a method parameter.

I am a bit worried about changing the method signature to LoadingValueReference though. Although I don't see it creating any immediate problems in the code, it feels weird that we are inferring the "is loading" information both from the type and by calling the method. Thus far I think the code relies on calling the method, not the type (this test p.e sets the loading property without being of type LoadingValueReference, and when overlooking the code I didn't see any instanceof / typecasts for LoadingValueReference but quite a lot of calls to isLoading()). I'm not sure if it's a good idea to introduce two ways of checking for this property.

Of course we at least need to check the type before retrieving the loading thread, but we could do it so that if the value isLoading() but is not of type LoadingValueReference we simply omit the recursion check (since we don't have a choice) but otherwise continue as usual, without throwing a ClassCastException.

I don't generally like that we rely on isLoading() instead of the type, but since we seem to be doing it everywhere else I think we should not make an exception here.

[cpovirk]

Oh, good catch! I had convinced myself that LoadingValueReference was the only type for which isLoading() was true, but I had neglected to look at the tests. I agree that the current setup is a little weird and also that it's not worth fighting against. I'll update my version and retest.

[cpovirk]

(I suppose that another option is to pull getLoadingThread() up into ValueReference and have it return null in the non-loading case. But it's probably safest to keep a clear delineation between the prod LoadingValueReference, which has the invariants that isLoading() is always true and getLoadingThread() is always non-null, and whatever it is that the test implementation does, which at present does not have such invariants :))

[cpovirk]

OK, back to your approach, just using valueReference instead, in https://github.com/google/guava/pull/6857/files#diff-98cf5b8d5ed981e94f4c745137a9b4ac3d0e896d0471cfb4e3baf85928c5053d

[cortlepp]

All right, let me know how when you find out anything new 👍.

[paggynie]

Hi! Multiple teams in our company recently pulled this commit and notice an obvious increase of Recursive load error. Based on latest change, this error is thrown when thread to load and get is same. I wonder did we consider the case where async refresh happened in another thread (not the thread that initiate the get/refresh). According to the code here, the thread that was stored before loadAsync happens and it's likely the loading thread that does actual loading happens in another thread.

Error message we have seen

java.lang.IllegalStateException: Recursive load of: 1e27da05-1b1f-4d0b-83e2-d474fa757111 | at com.google.common.base.Preconditions.checkState(Unknown Source) | at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(Unknown Source) | at com.google.common.cache.LocalCache$Segment.get(Unknown Source) | at com.google.common.cache.LocalCache.get(Unknown Source) | at com.google.common.cache.LocalCache.getOrLoad(Unknown Source) | at com.google.common.cache.LocalCache$LocalLoadingCache.get(Unknown Source) | at com.amazonaws.logs.caching.GuavaCacheProxy.get(GuavaCacheProxy.java:297)

I think what happened is
main-thread #1 call cache.get(key), triggers refresh, the loadingThread is marked as main-thread #1. However the actual loading thread is async-thread
then when main-thread #1 tries to call cache.get(key) again, it complains recursive load but it should not

[ben-manes]

can you provide a unit test to reproduce the problem? I think that would help expedite a fix.

[paggynie]

Thanks for quick reply. Here is my unit test and Im able to reproduce it.

Create cache loader with async refresh in another thread pool. Let async refresh to be a long process so that when key is expired (expiredAfterWrite), the async reload is still ongoing. And I notice the recursive load exception because it thinks the thread that tries to get the key is also doing the reloading (but it is not. The reloading happens in another thread)

@Test
    public void testRecursiveLoad() throws InterruptedException {
        ThreadPoolExecutor threadPoolExecutor = asyncCacheRefreshThreadPool();
        CacheBuilder<Object, Object> builder = CacheBuilder
                .newBuilder()
                .maximumSize(5000)
                // This acts as hard-timeout, where entries are removed after expire millis */
                .expireAfterWrite(20, TimeUnit.MILLISECONDS)
                // This acts as soft-timeout, where entries are asynchronously updated after refresh millis
                .refreshAfterWrite(10, TimeUnit.MILLISECONDS)
                .recordStats()
                .ticker(Ticker.systemTicker())
                .concurrencyLevel(Runtime.getRuntime().availableProcessors() * 2);


        CacheLoader<String, String> loader =
                new CacheLoader<String, String>() {
                    @Override
                    public String load(String key) throws Exception {
                        System.out.println("Time " + System.currentTimeMillis() + "Thread is loading: " + Thread.currentThread() + " with result: " + key + "load");
                        return key + "load";
                    }

                    @Override
                    public ListenableFuture<String> reload(String key, String oldValue) throws Exception {
                        ListenableFutureTask<String> task = ListenableFutureTask.create(
                                new Callable<String>() {
                                    @Override
                                    public String call() throws Exception {
                                        System.out.println("Time " + System.currentTimeMillis() + "Thread is reloading: " + Thread.currentThread());
                                        // mimic reload time to be long
                                        Thread.sleep(7000);
                                        return key + "reload";
                                    }
                                }
                        );
                        threadPoolExecutor.submit(task);
                        return task;
                    }
                };
        LoadingCache<String, String> loadingCache = builder.build(loader);

        ScheduledExecutorService singleThread = Executors.newSingleThreadScheduledExecutor(new CustomizableThreadFactory("main-single-"));
        singleThread.scheduleAtFixedRate(
                new Runnable() {
                    @Override
                    public void run() {
                        try {
                            String result = loadingCache.get("peach");
                            System.out.println("Time " + System.currentTimeMillis() + "Running thread: " + Thread.currentThread() + " result: " + result);
                        } catch (Exception e) {
                            System.out.println(e.getStackTrace());
                            e.printStackTrace();
                        }
                    }
                },
                10,
                5,
                TimeUnit.MILLISECONDS
        );
        Thread.sleep(5 *   // minutes to sleep
                60 *   // seconds to a minute
                1000);
    }

Result:

Time 1707281013332Thread is loading: Thread[main-single-1,5,main] with result: peachload
Time 1707281013358Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013359Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013360Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013360Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013360Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013360Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013360Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013363Running thread: Thread[main-single-1,5,main] result: peachload
Time 1707281013371Thread is reloading: Thread[AsyncCacheRefresher-1,5,main]
Time 1707281013400Running thread: Thread[main-single-1,5,main] result: peachload
[Ljava.lang.StackTraceElement;@87f932
java.lang.IllegalStateException: Recursive load of: peach
	at com.google.common.base.Preconditions.checkState(Preconditions.java:601)
	at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(LocalCache.java:2212)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2075)
	at com.google.common.cache.LocalCache.get(LocalCache.java:4036)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:4059)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:5041)
	at com.amazonaws.logs.cachinghealth.GuavaCacheProxySensorTest$2.run(GuavaCacheProxySensorTest.java:210)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
[Ljava.lang.StackTraceElement;@1de3a5ac
java.lang.IllegalStateException: Recursive load of: peach
	at com.google.common.base.Preconditions.checkState(Preconditions.java:601)
	at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(LocalCache.java:2212)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2193)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2081)
	at com.google.common.cache.LocalCache.get(LocalCache.java:4036)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:4059)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:5041)
	at com.amazonaws.logs.cachinghealth.GuavaCacheProxySensorTest$2.run(GuavaCacheProxySensorTest.java:210)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
[Ljava.lang.StackTraceElement;@12b96759
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)

This issue should happen when async fresh takes long enough that item got expired thus hit that logic (waitForLoadingValue)

[ben-manes]

Thanks! Then I think this change should be reverted.

When a refresh is scheduled by a cache read by the caller it creates a new LoadingValueReference, swaps it for the entry, triggers the asynchronous load, and returns back to the application. If it performs another cache read later and the entry expired, then it waits on the reload future and fails this check. I suppose that means Guava's expiration does not force the in-flight reload to be discarded, but I haven't inspected that code thoroughly enough.

This recursive check predated the addition of refreshAfterWrite so I hadn't considered that scenario. By luck the Thread.holdsLock approach nicely side steps this since it is checking the lock owner rather than the entry's creator. If the entry instead held a ReentrantLock then isHeldByCurrentThread would be the equivalent check. That would be an alternative fix, but I don't think its worth trying given that this broke unexpectedly and that code is not being actively maintained.

@cpovirk please review

[cortlepp]

We could also just not set the loader on creation, but rather directly before calling loadSync (in lockedGetOrLoad) though, right? So exactly at the place where there used to be the synchronized? Then the loader of course would have to be non-final, but other than that everything else could stay as-is.

But I understand If this is too high risk, since we already broke something...

[cpovirk]

Yes, I'll roll this back once I get in to work this morning. Sorry for the trouble, and thank you for the report.

(I don't love that I'm basically arguing to treat this code as "haunted" instead of actually working to find the best solution, but I think that's our safest bet at this point.)

[paggynie]

Thanks folks for quick action here and really appreciated for seeking for safest and best solution!
We can also include the UT (detect recursive load for async refresh/refreshAfterWrite) that I posted to enhance testing to guard rail such change next time

[cpovirk]

I got a bit sidetracked, but #6972 is now out for internal review.

@paggynie, if you're interested in contributing your test, you could send a PR to add it to LocalCacheTest. I would add it myself in my commit, but contributions require that you first sign a license agreement.

(Hopefully we'll just remember that this code is haunted and try not to touch it again, test or no test... :) But our team has many people on it, and even those of us directly involved might still forget.... Still, no pressure.)

[paggynie]

Thanks for rolling it back.
I need to work on adding myself in the Corporate Contribution Agreement within my company then I will file a PR to add test. Will keep folks here in the loop

[ben-manes]

@cortlepp-intershop You might want to try the new EA builds that no longer pin on synchronization. That might help you in general and they are asking for feedback. See their announcement for details.

[cortlepp]

@ben-manes Thanks so much for the heads-up! I already got the email and am currently evaluating the best way to cram their tarball into a container image. But however that will go, it makes me hopeful that there might be an official and released solution for monitors soon(ish).

[ben-manes]

@paggynie This is released in Guava 33.1.0 (I just saw @cpovirk's announcement in [email protected])

[smiroslav]

Hi @ben-manes @cpovirk
With this rollback, I suppose #6851 and #6845 remain unsolved.

I have started a thread in guava-discuss seeking some clarification
https://groups.google.com/g/guava-discuss/c/VkXCwqPsa5k