afterWrite blocks calling thread

[anuraaga]

We've been looking at an issue where sometimes CPU usage in our server binary spikes up and starts failing requests. We're not 100% sure the root cause is in caffeine but do see something somewhat unusual in thread dump.

There are many threads waiting here

"armeria-server-epoll-13-46" #216 prio=5 os_prio=0 tid=0x00007f274c012000 nid=0x144b7 runnable [0x00007f2948c2c000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Thread.yield(Native Method)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:914)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:1966)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:1893)
    at com.github.benmanes.caffeine.cache.LocalAsyncLoadingCache.get(LocalAsyncLoadingCache.java:125)
    at com.github.benmanes.caffeine.cache.LocalAsyncLoadingCache.get(LocalAsyncLoadingCache.java:117)
    at com.github.benmanes.caffeine.cache.LocalAsyncLoadingCache.get(LocalAsyncLoadingCache.java:156)

We run our logic on a small number of event loop threads, not on a massively threaded server, so it seems problematic for caffeine to be blocking our event loop threads for this write buffering. Is it possible to make this asynchronous? Alternatively, it seems like there is a (writeBuffers()) flag but I can't find how to modify it, a pointer would be great.

If it helps, the use case is a cache where 95% of the items will be accessed very frequently and should generally stay in the cache, while there will be LRU thrashing in the remaining as the actual data size is about 100x bigger than the cache.

[ben-manes]

Can you check which Java version you are running? You might have hit JDK-8078490.

The write buffer is bounded, but should only block when full. That is rare unless under a synthetic load. However a bug in the JDK causes ForkJoinPool to discard some tasks, which causes the buffer to be stuck. The write buffer is used to allow the cache to do work asynchronously, just as you were requesting.

[anuraaga]

Yeah we had noticed the issue here referencing the JDK bug and were excited to first try updating to 1.8u92 from an affected version of the JDK. But it didn't change what we're seeing unfortunately.

Also, just for an idea, 23 out of our 64 event loop threads are waiting at that same stack trace so it seems to be happening quite a lot.

[ben-manes]

Then that is very weird. It means that somehow the maintenance task is stuck and I don't know why. If we can reproduce that would be very helpful.

A quick fix is probably to set a different executor and see if that helps.

[ben-manes]

A quick hack to the stressing tool so far doesn't show any problems. The expectation is that the write buffer would be full, the drain status would be processing, but no thread was actually doing the work. If we can get that state to occur then we can determine what is wrong. I'm testing on 8u92 with a 4-core (8 SMT) macbook pro.

[anuraaga]

Yeah unfortunately currently have no leads on an easy repro, but we will first try replacing the executor to see if it helps and will report back.

[ben-manes]

I took another angle and began looking at refreshing instead of normal writes. I was then able to reproduce this being stuck in a bad state (Drain status = Processing -> Required) without a processing task running. I haven't been able to figure out yet why that happens.

For a synchronous cache using a same-thread executor (Runnable::run) resolves it. For an asynchronous explicitly calling cache.cleanup() periodically fixes it. Those are temporary workaround until we can figure out what is going wrong.

[ben-manes]

It also resolves itself if I use Executors.newCachedThreadPool() instead of ForkJoin. All of my debug logic shows clean entry and exist of the performCleanUp method. So this may be an issue where the executor is discarding our tasks, like the JDK one mentioned earlier.

Edit:
It seems any executor setting, except ForkJoinPool.commonPool(), does not exhibit this problem. Even Executors.newWorkStealingPool() which is another FJP seems to be fine. So it looks like something odd about the commonPool, as when I take away all other differences its the only one that triggers this failure.

[ben-manes]

I tried switching away from the state machine to a Semaphore(1) to transfer the lock state. This fails in the same manner, indicating that the state machine is not at fault. The log statements show the scheduling of the task, but the executor discarding it instead. Even when I change PerformCleanupTask to a simple runnable (to avoid FJP optimizations) this still occurs. So my best guess is that a bug in FJP is the root cause of the problems.

[johnou]

@ben-manes would you please share the reproducer?

[ben-manes]

Please see the issue 90 branch and run the Stresser. That can be done using your IDE (guide) or running the command ./gradlew stress. You should see output like,

scheduled drainBuffersTask
begin: performCleanUp -> 2
exit: performCleanUp -> 1
release: performCleanUp
acquire: scheduleDrainBuffers
scheduled drainBuffersTask

When using a FJP it will hang after scheduled drainBuffersTask. Any other executor type will continue and finish successfully.

The reason Executors.newWorkStealingPool() was successful is because I forgot to remove some debug code that switched to whenCompleteAsync which using commonPool. After reverting back it hangs too, as one would expect.

The reason the state machine was left in a bad state with FJP is because scheduling moves the state to Processing -> Idle to guard other scheduling attempts. A further write transitions it to Processing -> Required. Since the task wasn't run the state is stuck, causing the buffer to fill up and block.

I do not yet have this isolated to a FJP only test.

[johnou]

seems that once the FJP gets into the bad state no further tasks are executed (not sure if it recovers yet, only just started poking about).

        System.out.println("scheduling drainBuffersTask");

        CompletableFuture<Boolean> future = new CompletableFuture<>();
        executor().execute(() -> {
          System.out.println("invoking performCleanUp");
          future.complete(true);
          performCleanUp();
        });
        try {
          future.get(3000, TimeUnit.MILLISECONDS);
        } catch (TimeoutException e) {
          System.out.println("lock detected");
          executor().execute(() -> {
            System.out.println("never invoked");
          });
        }

[ben-manes]

Doug also started poking at it and, not surprisingly, this is probably my fault.

> It's weird to do with a Thread.yield anyway.

I had probably incorrectly assumed it would rarely be triggered, as the write buffer is set to
about 128 * NCPUs, and be used only to avoid starving the maintenance task's thread. That
was the case I had observed in write stress test (cache.put) with an unbounded queue, but
that required the machine be dedicated towards that goal. I hadn't considered the possibility
of starving the FJP through a completion callback, so changing to a more conventional scheme
sounds like the right solution.

On Sun, Jun 12, 2016 at 3:37 PM, Doug Lea <dl@cs.oswego.edu> wrote:
On 06/12/2016 06:30 PM, Benjamin Manes wrote:
> Since there are not many examples of ManagedBlocker, I've never been comfortable
> using it. Its a bit of black magic that I'd need to play with to fully grok.

It's weird to do with a Thread.yield anyway.
The best diagnose would be if you replace that yield with
a condition wait of some sort triggered by whatever that other thread
does.

> By setting WRITE_BUFFER_MAX to a small value (e.g. 8) and using
> newWorkStealingPool(512), I see only 110 FJP worker threads in the stack dump
> when it halts. Would that be indicative of an issue beyond not using ManagedBlocker?

Conceivable.
But I haven't been able to see any effect that looks like a FJP issue.

-Doug

On Sun, Jun 12, 2016 at 3:08 PM, Doug Lea <dl@cs.oswego.edu
<mailto:dl@cs.oswego.edu>> wrote:

    Do you have enough parallelism in pool to run?
    I see all workers spinning on
             at java.lang.Thread.yield(java.base@9-ea/Native Method)
             at
    com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:910)
             at
    com.github.benmanes.caffeine.cache.BoundedLocalCache.replace(BoundedLocalCache.java:1907)

    If you can't guarantee enough workers, you could use a ManagedBlocker here.

    -Doug

[ben-manes]

Thanks for taking a look and showing where I made a poor oversight.

I think the right solution is to replace Thread.yield() with a call to performCleanUp(), or a variant. That would block the thread on the eviction lock and help out by performing the maintenance work. Since the thread would otherwise be waiting anyways, there it wouldn't be incurring a significantly higher penalty for this degredation mode. Switching to that call now passes the stress test and doesn't seem nearly as awful as the ad hoc yield.

I need to think about whether to use performCleanUp(), what an optimal variant might be, and if there is a better alternative. But thanks to yours and Doug's generous assistance I think we have a potential fix.

[anuraaga]

Thanks a lot for helping on this! Also glad to see that it looks like Stresser now has a case closer to our production usage (all get / refresh, no puts) to keep us safe going forward. :)