Caffeine: Deadlock in NonReentrantLock

[agoston]

Under heavy load of JVM, we are experiencing deadlocks in caffeine version 2.5.6.

Here is the threaddump of the two threads in deadlock:

"ajp-0.0.0.0-8109-59 (P6V7aMaZbbXkfaYzYzXxID0tvHylFQJumanAAABmA)":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000032a600bb8> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
        at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1017)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1655)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1602)
        at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

and

"ajp-0.0.0.0-8109-78 (-jIkyghhBePEsLll9i5dnGr65Dx8PfahGe2gAABxE)":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000032a600bb8> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
        at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1017)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1655)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1602)
        at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

Looking at the code, I can't imagine a scenario this could occur, but it _does_ occur under heavy load of our JVMs.

Any ideas what we could do? For now, as a workaround, I've added a synchronized() block around the cache.put() methods to make sure only 1 thread is adding new values to the cache at a time.

[ben-manes]

I’m sorry to hear this.

I didn’t think this could happen either, at least with the ForkJoinPool. If
a custom pool (even just commonPool()::execute) it uses a normal
ReentrantLock. I think you could switch to that until we have a fix ready.
See Caffeine.executor

The difference is negligible so we could switch over, as I was perhaps
overly aggressive when experimenting. I would like to figure out a unit
test to assert the deadlock first, though.

On Tue, Nov 14, 2017 at 1:52 AM Agoston Horvath [e-mail]
wrote:

Under heavy load of JVM, we are experiencing deadlocks in caffeine version
2.5.6.

Here is the threaddump of the two threads in deadlock:

"ajp-0.0.0.0-8109-59 (P6V7aMaZbbXkfaYzYzXxID0tvHylFQJumanAAABmA)":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000032a600bb8> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1017)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1655)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1602)
at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

and

"ajp-0.0.0.0-8109-78 (-jIkyghhBePEsLll9i5dnGr65Dx8PfahGe2gAABxE)":
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000032a600bb8> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1017)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1655)
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1602)
at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

Looking at the code, I can't imagine a scenario this could occur, but it
does occur under heavy load of our JVMs.

Any ideas what we could do? For now, as a workaround, I've added a
synchronized() block around the cache.put() methods to make sure only 1
thread is adding new values to the cache at a time.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/ben-manes/caffeine/issues/203, or mute the thread
https://github.com/notifications/unsubscribe-auth/AAXG9tZtHiwrHd_nAkTkRnGwUXyTupGtks5s2WLngaJpZM4QdEQj
.

[ben-manes]

Looking at the stack, if these are the only threads blocked then it looks like a lost unlock signal. But of course I can't reproduce this using my Stresser utility. If this works fine with ReentrantLock, at least we'll know its a bug somewhere around this logic.

This code path should only occur when the write rate exceeds the drain rate, or that the drain task was lost such as due to the ForkJoinPool bug on older JDKs. The write buffer typically allows writes to make progress by batching the work onto the penalized thread, but if filled it will block on the lock. That improves performance by descheduling the threads, increasing overall throughput by reducing context switches.

A few questions to help investigate:

• Does using Caffeine.executor(ForkJoinPool.commonPool()::execute) solve the problem (trick it to use a ReentrantLock by not trusting the FJP).
• Are there any other stacktraces using the cache not shown?
• What is the cache configuration? (e.g. Is a CacheWriter doing heavy work?)
• What version of the JDK are you running?
• Any other suggestions for how to reproduce?

[agoston]

I've checked ReentrantLock vs. NonreentrantLock, but in the end, they both end up in AbstractQueuedSynchronizer.acquire(), which is where the problem occurs.

All the stacktraces are in this code path, there is no difference. I do get a deadlock warning from JVM (this is the full output, the other 2 threads are not relevant here, they are waiting on locks held by the 2 threads deadlocked above):

Found one Java-level deadlock:
=============================
"ajp-0.0.0.0-8109-128 (-jIkyghhBePEsLll9ic8a19e79f354)":
  waiting to lock monitor 0x00007f73f881a308 (object 0x0000000508b1d908, a com.bol.order.CustomOrder),
  which is held by "ajp-0.0.0.0-8109-78 (-jIkyghhBePEsLll9i5dnGr65Dx8PfahGe2gAABxE)"
"ajp-0.0.0.0-8109-78 (-jIkyghhBePEsLll9i5dnGr65Dx8PfahGe2gAABxE)":
  waiting for ownable synchronizer 0x000000032a600bb8, (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync),
  which is held by "ajp-0.0.0.0-8109-36 (P6V7aMaZbbXkfaYzYzkTBzHO7PeW5fQUKx8QAAAao)"
"ajp-0.0.0.0-8109-36 (P6V7aMaZbbXkfaYzYzkTBzHO7PeW5fQUKx8QAAAao)":
  waiting to lock monitor 0x00007f73d40846a8 (object 0x000000048855c020, a com.bol.order.CustomOrder),
  which is held by "ajp-0.0.0.0-8109-59 (P6V7aMaZbbXkfaYzYzXxID0tvHylFQJumanAAABmA)"
"ajp-0.0.0.0-8109-59 (P6V7aMaZbbXkfaYzYzXxID0tvHylFQJumanAAABmA)":
  waiting for ownable synchronizer 0x000000032a600bb8, (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync),
  which is held by "ajp-0.0.0.0-8109-36 (P6V7aMaZbbXkfaYzYzkTBzHO7PeW5fQUKx8QAAAao)"

JVM version is 1.8.0u131.

Cache configuration:

    @Bean
    public Cache myFluffyCache() {
        return Caffeine.newBuilder()
                .maximumSize(10_000))
                .expireAfterWrite(1, TimeUnit.DAYS)
                .recordStats()
                .build();
    }

We can not reproduce this bug, it only happens on production, very sporadically (a few times a week, then nothing for months, then returns to few times a week).

I was thinking of replacing evictionLock construct by a simple synchronized(this). I'm not sure what the upside of using reentrantlock is, but is sure more error-prone. Make sure you check out this document:

https://bugs.openjdk.java.net/browse/JDK-8156765

which, in turn, is caused by a serious design flaw in java.util.concurrent that is only fixed by an epic hack in java9:

https://bugs.openjdk.java.net/browse/JDK-7011862

[ben-manes]

I've checked ReentrantLock vs. NonreentrantLock, but in the end, they both end up in AbstractQueuedSynchronizer.acquire(), which is where the problem occurs.

Yes, but perhaps my NonreentrantLock has a bug that is hard to trigger. It is a slimmed down ReentrantLock since I don't expect recursive locking, and tried to build out everything upfront and before I got demotivated by the weight of the project's complexity. While it is faster in a dedicated microbenchmark, it isn't a hot path and probably should be removed as unnecessary.

I was thinking of replacing evictionLock construct by a simple synchronized(this). I'm not sure what the upside of using reentrantlock is, but is sure more error-prone.

Unfortunately synchronized does not support _try-lock_ semantics. When scheduling is performed (scheduleDrainBuffers), a tryLock is used to skip past it if another thread is taking care of it. That avoids unnecessary blocking and is simpler than trying to emulate it using a synchronized and CAS'd boolean, which might work but feel a little error prone.

All the stacktraces are in this code path, there is no difference.

Do your logs include any warning like Exception thrown when submitting maintenance task? This would be if the executor threw an exception unexpectedly, such as a RejectedExecutionException. That shouldn't occur on a FJP unless the system is in a bad state, as it allows for up to 64M tasks. A problem like OutOfMemoryError might occur though, but the tests should cover that case. But I don't know when the lock could be left in a blocked state, resulting in a pile-up, if assuming it is a bug within BoundedLocalCache.

So I'd still recommend trying the trick to force ReentrantLock and seeing if this occurs. But other than that guess, there isn't enough information for me to debug with.

[agoston]

Do your logs include any warning like Exception thrown when submitting maintenance task?

No, I see nothing of the sort.

Forcing the reentrantlock is not so simple, as the code in BoundedLocalCache goes like this:

    evictionLock = (builder.getExecutor() instanceof ForkJoinPool)
        ? new NonReentrantLock()
        : new ReentrantLock();

So the recommended FJP::commonPool() would still use a NonReentrantLock.

[ben-manes]

Nope, it would be an anonymous executor and use a ReentrantLock.

$ javarepl
Welcome to JavaREPL version 425 (Java HotSpot(TM) 64-Bit Server VM, Java 1.8.0_144)
Type expression to evaluate, :help for more options or press tab to auto-complete.
Connected to local instance at http://localhost:53166
java> import java.util.concurrent.*
Imported java.util.concurrent.*
java> Executor e = ForkJoinPool.commonPool()::execute;
java.util.concurrent.Executor e = Evaluation$7adjq3cgmtr50ps9z6b4$$Lambda$211/634150796@6a757ee
java> e instanceof ForkJoinPool
java.lang.Boolean res1 = false

[agoston]

👏, neat :)

I will push a test to production. Note that since this issue is not reproducible manually, I won't be able to say if it's fixed or not.

[ben-manes]

Sounds good. I'll switch over regardless and close this when released, assuming this doesn't occur again. If it does occur afterwards, we should revisit with the new stacktrace. I won't get a chance to look at this until after the holidays, so that should give us some time to see if it reproduces.

[levischuckeats]

Commenting here, as we are also affected. It seems to only happen on production and at odd hours. Today (the third event) happened on a server with little to no load at these hours.

The stack trace is the same as far as I can tell above. This was with version 2.5.5.

  - parking to wait for  <0x00000002cdaff260> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
        at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1017)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1655)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1602)
        at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

We use an async weigher which uses a pessimistic (largest object of that class so far) at first, then in a thread pool it will re-insert the object with a thread local set, such that it is actually weighed within that thread pool. So most objects are inserted twice under the same key.

            AsyncWeigher<Object, Object> weigher = asyncReference.get();
            cache = Caffeine.newBuilder()
                    .maximumWeight(1024l * 1024l * 1024l * GIGS_OF_CACHE)
                    .weigher(weigher)
                    .build();
            weigher.setCache(cache);

[ben-manes]

Can you also try changing to use a ReentrantLock so we can see if it reoccurs?

Caffeine.newBuilder().executor(ForkJoinPool.commonPool()::executor)...

The inability to reproduce and eye balling the code, I haven't stumbled upon the likely cause. So I don't have much advice yet except bypass the most likely culprit.

Do you see IllegalMonitorStateException in your logs? Also, can you list which methods you use on the cache? Perhaps the exclusiveOwnerThread is not properly set/unset causing it to block. There are explicit lock() calls in a few non critical paths, so perhaps its a race between lock/tryLock.

[levischuckeats]

Hello @ben-manes
Due to the holidays, we won't be deploying significant code changes this week, so I won't be able to try this out.

As for IllegalMonitorStateException, there are no error logs that include that in the stacks from any of our servers.

We currently use the following functions (duplicates for specific types that we use, if it makes a difference):

• invalidate(Long)
• invalidate(Object)
• put(String, Object)
• put(Object, Object)
• invalidateAll()
• getIfPresent(Long)
• getIfPresent(String)
• getIfPresent(Object)
• getAllPresent(Collection)
• .asMap().remove(Long)

[ben-manes]

Yep, due to the holidays I don't plan on fixing it this week either =)

Thanks. invalidateAll() does use lock() since clearing is going to be an expensive operation and the alternative path would be slower. So next step would be to see if Stresser test could reproduce it with a mix of calls. However, this is done by MultiThreadedTest so I'd have expected it to fail during a CI run in the past.

[levischuckeats]

invalidateAll in our code is rarely used and really only comes to play in a single threaded situation where the server just finished running migrations before becoming available to the outside world.

So I wouldn't focus on that.

[ben-manes]

Right, I'm trying to think of lock interactions that could be stress tested in an attempt to reproduce the problem. Maybe I should write a dedicated stress test on the lock class itself to see if I can break it, so we are sure about where the bug lies.

[levischuckeats]

While preparing a censored jstack to share (if you so wish to see, reach out to [email protected] ), here are the counts I saw.

• 378 threads were stuck on com.github.benmanes.caffeine.cache.LocalManualCache.put
• 136 threads were stuck on com.github.benmanes.caffeine.cache.BoundedLocalCache.remove
• 4 threads were stuck on com.github.benmanes.caffeine.cache.LocalManualCache.invalidate
• 9 threads were stuck on com.github.benmanes.caffeine.cache.BoundedLocalCache.replace

There was one thread in a fork join pool that was made to do a clean up, but it didn't get anywhere

    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
    at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1096)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache$PerformCleanupTask.run(BoundedLocalCache.java:2963)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache$PerformCleanupTask.exec(BoundedLocalCache.java:2952)

[levischuckeats]

Interestingly.. as I was censoring the jstack and getting those numbers, the same server had a deadlock with caffeine again.

[ben-manes]

I'm sorry for the inconvenience this is causing. I'm surprised its happened all of a sudden, since that code wasn't changed recently and its had heavy usages and stress tests. I wonder if its a JDK change around memory fences, perhaps a newer optimization triggering this bug.

[levischuckeats]

It's really odd, because we have not updated in a while but it is only happening this last week and now.

These servers are running with about 10GB of cache (GIGS_OF_CACHE being set to 10 in the builder above), and are running with java -version

java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)

[jbduncan]

@levischuckeats Am I right to assume that this Java version you're running is some sort of build of OpenJDK? :)

[levischuckeats]

@jbduncan

I don't think so, the folder our java bins are in is named java-8-oracle, the COPYRIGHT mentions oracle in name, there's a release file that says commercial under build type. The README just points to java.com

[ben-manes]

When I run the Stresser in write mode on 8_144, I see the lock holder change over time.

---------- 00:01:34 ----------
Pending reads: 0; writes: 1,024
Drain status = Processing -> Required (3)
Evictions = 325,998,568
Size = 5,136 (max: 4,096)
Lock = [Locked by thread pool-2-thread-1]
Pending tasks = 2
Max Memory = 3,817,865,216 bytes
Free Memory = 158,083,696 bytes
Allocated Memory = 481,820,672 bytes

---------- 00:01:39 ----------
Pending reads: 16; writes: 153
Drain status = Processing -> Required (3)
Evictions = 343,609,572
Size = 5,494 (max: 4,096)
Lock = [Locked by thread pool-2-thread-13]
Pending tasks = 0
Max Memory = 3,817,865,216 bytes
Free Memory = 155,875,704 bytes
Allocated Memory = 318,767,104 bytes

There are stacks of blocked threads, but that is because the write buffer was filled. Rather than being unbounded, it adds back pressure to block threads by helping to perform a full cleanup. In the common case writes are processed asynchronously to minimize user-facing latencies, and in the write storm it throttles when overwhelmed. The throttling improves throughput by reducing context switching.

"pool-2-thread-7" #24 daemon prio=1 os_prio=31 tid=0x00007fcc0584a000 nid=0x7003 waiting on condition [0x0000700011e01000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000006c0ca3650> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
    at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1100)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1021)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1658)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1606)
    at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)
    at com.github.benmanes.caffeine.cache.Stresser.lambda$run$2(Stresser.java:103)
    at com.github.benmanes.caffeine.cache.Stresser$$Lambda$8/517380410.call(Unknown Source)
    at com.github.benmanes.caffeine.testing.ConcurrentTestHarness.lambda$timeTasks$0(ConcurrentTestHarness.java:83)
    at com.github.benmanes.caffeine.testing.ConcurrentTestHarness$$Lambda$9/1681433494.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

I would have expected the lock holder to be stuck and, potentially, the throughput to drop as if all threads get blocked. So this is frustrating since I cannot reproduce...

[levischuckeats]

I understand the back pressure, though when the CPU for all cores is near 0, I don't think work is being done 😃

For our use case (an intermediate cache for entities, which are backed by the database), we'd prefer things getting dropped, rather than being blocked.

[ben-manes]

@agoston By any chance are you running this on Tomcat? In a private stacktrace from @levischuckeats, he mentioned the threads are from Apache Catalina (Tomcat's servlet pool). I know the Tomcat class loader can cause problems, especially when shared classes like FJP are in the mix. I wonder if it is an interaction because of the container...

[ben-manes]

Yep, if the system isn't generating writes then we'd all expect the cache to catch up and quickly be idle.

A write cannot be dropped, since those are add/update/remove operations already performed on the hash table. Think of it as a database write-ahead log. The writes are applied in-memory, appended to a log, and replayed on the persisted form. In this way the expensive operation (random fsync) are batched and asynchronous, helping to scale throughput. The cache is similar, where the locking around the eviction policy is expensive because every read/write is a policy mutation. We can and do drop reads, which is the common case and non-critical state. But writes may effect things like require an eviction.

[agoston]

@ben-manes
correct, we are running under tomcat (jboss to be even more precise). The thread names are telling it already (ajp-* are tomcat's AJP worker threads).

[ben-manes]

Any chance you have clearReferencesStopThreads enabled? That uses Thread.stop() and I’m wondering if a redeployment causes the lock to be left in a bad state due to halted threads.

Also what version of Tomcat and did you recently upgrade?

[levischuckeats]

On our end, we actually kill java when we redeploy, so every time Tomcat is running for the first time in the JVM.

[agoston]

I wonder if we work at the same company @levischuckeats :) we do the same thing, we do a rolling restart only, never redeploy.

[ben-manes]

I'm stuck then, because I can't work out the failure conditions.

• All usages of the lock use the correct lock then try / finally unlock idiom
• No calls have recursive acquisitions excluding foreign code
• The shown configurations do not have foreign code that recurses under the lock
• Tests against the cache (Stresser, MultiThreadedTest) don't show problems
• An isolated stress test against the lock shows progress
• No weird behavior like Thread.stop() to explain it away
• Independent failures so not a user problem (e.g. infinite loop)

The only similarity so far is Tomcat which can be invasive, but not so much in your usages. I haven't used Tomcat in many years (preferring embedded Jetty) so I'm not good at debugging it anymore. But it also feels like a copout to presume its a weird interaction bug.

I'm back to having to wait until sometime after the holidays when you both can test using ReentrantLock to see if the problem disappears or a similar stack emerges. If you have any better suggestions please let me know.

[ben-manes]

It would also be helpful if you track the cache stats. Then we could know for certain that eviction halted. Otherwise my testing only shows threads backed up, but progress continues. If I add a shutdown hook, then they all quickly complete normally. I cannot reproduce any hanging.

[ben-manes]

I spent a good amount of time on this today, since I had the day off. Unfortunately I am no closer but did discover a bug in the AsyncLoadingCache#synchronous()#asMap() view when it emulates a synchronous computation. That's not shown in your configurations, but thought I'd double check since it did allow for a deadlock scenario (e.g. future writing back into the cache for that key).

[ben-manes]

The only scenario that I can think, but cannot reproduce, is if FJP ever degrades to a caller-runs policy. If the pool detects that the caller is a ForkJoinWorkerThread and it cannot push to local or external queues, then perhaps the worker tries to run the given task directly. This would cause unexpected recursion when the drain task is scheduled under the lock, directly executed, and thus a deadlock. But nothing in FJP indicates it tries to help out this way, nor can I trigger any deadlock scenarios. This would be resolved using a reentrant lock, which is why we degrade to it for a non FJP, yet I cannot reproduce or eyeball code that might be the symptom.

@agoston suggested JDK-8156765, but there isn't enough detail to debug with.

[levischuckeats]

I was planning to add metrics to our cache wrapper anyway 😃

As for the asMap stuff, I don't think we do any call to synchronous. Our use case is return cache.asMap().remove(key) != null; for a delete call to our wrapper.

I wasn't behind the original writing as to why asMap is used.

[levischuckeats]

It looks like there's no invalidate / remove method exposed by Caffeine directly that returns whether or not the key was found and subsequently evicted. If that asMap functionality has a bug there, that may explain what we are seeing with one or two servers dying at the same time.

We have server-local caches that rely on Caffeine for entities. To prevent stale data from reaching the end user, we have a pub-sub bus that every server publishes to when it updates an entity, all other servers listen and drop the entity from the local cache so the next load goes to the database. It really isn't the most efficient or smart mechanism, but it works for the small cluster we have.

These crashes are happening often around 4 AM Central time, which is when we run a lot of jobs--so one server is dirtying a lot of entities at once, and other servers subsequently have caffeine deadlock as they attempt to remove all of those entities from local memory cache.

Assuming the deadlock is possible from the asMap, which is only used by us in removing things from the cache, it would explain the timing and multiple server problem.

The reason why we need a boolean on whether or not an object was removed from the cache is because we also have some indexes on entities in memory to keep up to date.

[ben-manes]

The asMap in a synchronous cache seems fine, which is what you've shown before. The asMap for an asynchronous cache (one that stores futures) had a potential deadlock bug. It has to emulate a synchronous cache for the view, since the entry is present but the future is in-flight. It was incorrectly waiting on the future within the map computation, and the stack traces were much more obvious. You would create such a cache using Caffeine.buildAsync.

Thanks for the additional information, though.

[levischuckeats]

I now have monitoring in place, initially load counts are around:
getIfPresent: 3,200,000 per minute
put: 22,600 per minute
asMap().remove: 14,200 per minute

The next time we get a crash, I can get some load counts to see if they are particularly different.

Latency has an average of <1 ms (registers as 0 for currentTimeMillis - before) per operation.

[ben-manes]

Thanks! I am particularly interested in two outcomes,
a) w/ NonReentrantLock: Do evictions still occur or is that halted (evictionCount)
b) w/ ReentrantLock: Does the error appear to be resolved?

If (a) then this would indicate it isn't a problem with the cache and a write storm is present, e.g. an infinite loop, causing it to be backed up. The write buffer grows to a decent size so that shouldn't happen very often, e.g. except when warming on startup.

If (b) then we can release with the switch. I'd really like to understand the problem, with a test to assert its fixed, rather than blindly change code. But I don't think its a bad change to do regardless.

[levischuckeats]

I can add minute-granularity collection of more metrics, but I don't see things like eviction count exposed on the Cache interface.

Again for reference, this is how we build our cache.

cache = Caffeine.newBuilder()
                    .maximumWeight(1024l * 1024l * 1024l * GIGS_OF_CACHE)
                    .weigher(weigher)
                    .build();
            weigher.setCache(cache);

Per the stack traces in the jstack, it seems this uses NonReentrantLock.

I see you mention Caffeine.executor(ForkJoinPool.commonPool()::execute)

Are you suggesting something like:

cache = Caffeine.newBuilder()
                    .maximumWeight(1024l * 1024l * 1024l * GIGS_OF_CACHE)
                    .weigher(weigher)
                    .executor(ForkJoinPool.commonPool()::execute)
                    .build();

?
How much risk do you associate with this change? What performance impact might it have?

Once 18 or so hours pass, I can provide some more numbers for both natural load and nightly job loads.

[ben-manes]

To record statistics, please enable Caffeine.recordStats() and export it using Cache.stats(). The CacheStats includes useful information like evictionCount.

The default for Caffeine.executor is ForkJoinPool.commonPool(). If you put in your own non-FJP executor, we use a ReentrantLock since the interface allows it use caller-runs or throws an exception on rejection, both of which should not occur on a FJP. By using the method handle, it gets an anonymous Executor wrapper but still does the work in the pool, meaning just an extra method dispatch. The performance difference between the lock types went away when optimizing the internal state machine, so there isn't a justification (if there was one to begin with). So, the impact should be non-existent.

[levischuckeats]

Alright. I'll see what I can do to canary these changes the next day.

[levischuckeats]

I don't think I'll be able to make these changes this week, but here's the max numbers within a server (not a sum of multiple servers) encountered during the times we saw crashes in the past.
get: 55,916,000 / minute
put: 697,300 / minute
remove: 201,000 / minute

[ben-manes]

I have tried that mixed workload in the Stresser tool. However, I have only been testing on my macbook (4c/8ht). Perhaps this is only reproducible on the OS or CPU-family?

[ben-manes]

The write rate is quite high (17k/s) and the write buffer has a maximum size of
128 * ceilingPowerOfTwo(NCPU), which I actually think might be too high. Assuming you have 32-cores, then this would absorb 4k concurrent writes before back pressure is applied.

However, this should not deadlock and your stack traces should show a thread in the maintenance method doing the work.

[levischuckeats]

Just a simple 8 core server :)
To be specific the cores seem to be Intel(R) Xeon(R) CPU E5-2676 v3 @ 2.40GHz

Again, those numbers are the maximum of any of the servers with minute granularity. The spikes I saw for this were when major nightly jobs were running--loading all sorts of relational stuff.

[ben-manes]

I guess it isn't a dedicated machine, since that is a 12-core / 24-threads processor. Some cloud providers disable hyper-threading, so its either 8 or 16 "processors" according to Runtime.availableProcessors(). I guess we can estimate either a 1k or 2k write buffer size.

Given the write-rate is high enough to exhaust the write-buffer, you should see threads blocking on the lock. But you should also see a high throughput as the maintenance() work processes the buffer (up to the size limit for amortization). Thus a lot of writers should refill the buffer and progress, with the blocked writers context switched out to help improve overall throughput. Since the work under the lock is inexpensive and batched, there should be decent performance even under this high load.

You could play with the Stresser utility to see how it behaves and does a good job at progressing.

Are you sure this is deadlocked and borked, or merely working through the backup? From the stacktraces you sent earlier it does seem deadlocked, but again I can't reproduce which is frustrating.

Oh, what OS are you running? We should try to spin up a similar instance and run the Stresser on it to see if its reproducable there. Then might be a kernel/JVM bug of a lost signal, which would explain a lot.

[levischuckeats]

Ubuntu 15.04 (GNU/Linux 3.19.0-22-generic x86_64)
Amazon m4.2xlarge apparently
Htop shows 8, cat /proc/cpuinfo shows 8 entries too.

I could see how a missing signal might derail all of this. But I am perplexed as to why the clean up thread is also blocked on the same lock.
When this happens, there is no load by the time we find out, everything is either sleeping or parked on that lock. (anything that could touch the database goes through Caffeine first.) Htop showed practically idle on all cores at the time I took that jstack.

I now have code for internal review in to monitor the internal caffeine stats (collecting internally every 10 seconds, logging totals every 60 seconds), as well as a way to canary the alternate executor on specific instances. But don't expect results until next week.

[ben-manes]

Thanks for your patience and helping to work through this. I hope its not causing too much disruption.

The clean-up thread is the preferred approach because it hides any of the maintenance work from user-facing threads. Whenever a write or enough reads occur, it is scheduled to be run. The writers then degrade to doing the work themselves if the buffer is full. Usually that's because the application is already using all of the threads in the pool for longer running tasks (e.g. rpc futures). The intent is that by default we hide cheap maintenance latency, but degrade to make progress otherwise.

I don't know why all the threads are blocked trying to acquire, since the usage idiom of lock/unlock and AbstractQueuedSynchronizer appear correct. A lost unlock() signal that is OS/CPU specific is the only explanation so far. But if ReentrantLock solves it, then that's better to be my bug then us digging into kernel tickets.

[ben-manes]

I wonder if you are hitting this Linux lost wake-up bug? In this thread by Gil Tene, it seems to be occurring on Ubuntu 15.04:

I'm seeing a similar problem on kernel 3.19.0-16-generic after having upgraded Ubuntu to 15.04 (Vivid Vervet). However, checking the github link above indicates that the fix should be in 3.19, so I'm not sure if this is a regression or something else.

I've documented what I'm seeing here: http://ubuntuforums.org/showthread.php?t=2278238&p=13285416#post13285416 (I'm not really familiar with Linux debugging, though, so I'm not sure if I'm reporting the right information.)

Basically, certain Java applications are regularly hanging, and when I run strace I see them in FUTEX_WAIT. So far it's affecting only Java, but this includes previous versions of Java that have been working for a long time.

Paul Blair

Another user reported that the patch is in your version, but he still sees the problem in JDK8:

I'm seeing the same thing on the same version of Ubuntu with a Haswell when running Jetbrains CLion (which runs in Java). It hangs on a futex and I have to kill the program to unlock it. Binding it to a single core seems to avoid the hang but kills performance. I checked Ubuntu's version of the 3.19 kernel source and the patch is in there.

It does seem to be somehow related to Java 8 vs Java 7. When I installed Oracle JDK 7 and forced CLion to run it, I no longer see the hang.

Jack Bradach

And finally it was stated that Ubuntu 16.04 is fine,

I never found the exact fix but I do know that 4.4.0-65 (Ubuntu 16.04 LTS)
is also fixed so somewhere between that and at least 4.2.0-18 lies a problem

Daniel Worthington-Bodart

[levischuckeats]

Ben,

Thank you for sharing your research into the kernel java futex problem.
This week I am on call, and I will be canarying the alternate executor for a day. If nothing bad happens on that server, I'll make half the servers (including the ones that crashed prior) run on the alternate executor.

On my end, we still don't know what made those few days rather sensitive to crashes, but it seems to have disappeared.
This may be a very slowly moving ticket as mentioned by agoston.

Perhaps getting agoston's environment details may corroborate this.

[ben-manes]

@agoston Can you provide the cpu and operating system for your servers?

So far, the kernel bug is the most likely culprit since I cannot reproduce on OS X. I haven't yet tried debugging on a Haswell / 15.04 box, which I think would be a good next step. If the Stresser fails there and then passes on 16.04, that should confirm it. I won't get a chance until maybe this weekend, unless anyone else wants to give it a go.

@levischuckeats Do you think your fleet could be upgraded to 16.04 LTS or newer? (Note that it is YY.MM, so you are running a 2.5yr old release)

[agoston]

@ben-manes I'm right here, just can't add anything -- because of season peak load, we allow critical fixes on production only. The synchronized{} hack I've outlined in OP held up well (and it was a non-performance-critical path, too).

We've got about 50 caffeine Cache instances, and only this very specific one shows issues. I'm unsure why this happens, there seems to be some deeper issue. See, before caffeine, we used ehcache, which was replaced to get rid of a weird deadlock in there, at the very same code path. But looking at the code in ehcache (v2.10), it was totally explainable -- it had infinite while(true) {} in there at key locations.

In the new year, we're beginning to kill off this code path completely (not because of this -- we're migrating away from jboss and similar EE-style solutions), so I don't think I will be able to further reproduce this problem.

As for the OS, it's a CentOS7, on 32 core xeon's, some insane amount of ram, and an uber-tuned GC (java8 + CMS, tuned for best throughput and low GC overhead). There are multiple such JVMs running on one physical box.

[ben-manes]

Thanks @agoston. In that thread,

Thanks Gil,
I can confirm kernel-3.10.0-229.4.2.el7 shipped with Centos7.1 is impacted.
It has 3.14 b0c29f79ecea0b6fbcefc999e70f2843ae8306db backported but not the 3.18 fix: 76835b0ebf8a7fe85beb03c75121419a7dec52f0

I filed a bug with Centos:
http://bugs.centos.org/view.php?id=8803

-adrian

So I think the kernel bug is a good candidate. It would explain your deadlock in Ehcache, too, if their infinite loops appeared correct. Do you think that you could upgrade your fleet's OS?

[levischuckeats]

Indeed upgrading our fleet is desirable. I don't think it will happen this month though.

So far the canary is behaving well, so I will put half on the alternate executor on the next deploy.

I have more numbers now: at most only 36 evictions are happening per minute, the average is around 7 evictions per minute.

[ben-manes]

I presume this has been working fine? If so, I'll make the switch over and release. I'll probably close this sometimes in January if it doesn't reappear.

[levischuckeats]

No events on my end for the normal executor, nor the alternate thread pool executor.

[levischuckeats]

Had a crash this morning at around 2:06 AM central, though it was only identified at 3:48 AM

Before the event, the internal metrics that Caffeine gave back had about 2K/misses per minute, and about 1K/evictions per minute.
Immediately at 2 AM, suddenly 53K/evictions per minute and about 51K/misses per minute.

The period this spike lasted was about 6 minutes and then the metrics are silent.

Unfortunately it seems something broke in my counting of which external methods we called on Caffeine, so I can't say what put/remove/get kind of interaction there was.

[ben-manes]

Is this with the executor tweak or without?

[levischuckeats]

This crash happened on a server without the executor tweak active.

[johnou]

@levischuckeats any OOMs or other exceptions logged?

[levischuckeats]

@johnou No, no OOMs, we get scary alerts when those happen.

Unfortunately our logging looks at configs which are backed by the cache, so when Caffeine dies, pretty much everything else we can review goes silent.

[ben-manes]

Released. I haven't had a chance to reproduce on a VM, but this removes the need for the executor trick to coerce the lock type.

[levischuckeats]

Alrighty, I'll update our deps and remove the canary code. May get deployed next week.

EDIT: actually will be deployed today, oh my.

[ben-manes]

I plan on closing this at the end of next week, unless there is new information to point to a cause other than the Linux kernel bug.

[agoston]

I was always under the impression that it is a JVM/other bug, so I don't mind.
Thanks a lot for your investigation and support! And of course for this awesome library.

[ben-manes]

Thanks!

The Linux commit acknowledges that it had deadlocks. So if possible please do upgrade.

The consequence is a race with a thread waiting on a futex on another CPU, allowing the waker thread to read "waiters == 0" while the waiter thread to have read "futex_val == locked" (in kernel).

Without this fix, the problem (user space deadlocks) can be seen with Android bionic's mutex implementation...

[levischuckeats]

I'm fine with this being closed.

We dearly need to upgrade, there aren't even repos for the ubuntu version we are on anymore D:

Anyway, thank you for your time and effort into this Ben, I really appreciate it.

[ben-manes]

Thanks guys!

[ractive]

Hi guys

Unfortunately we're facing the exact same issue running a webapp with Spring Boot using an embedded tomcat inside a kubernetes cluster. The kernel version of the coreos hosts is 4.14 - so pretty recent.
From inside the docker container:

# uname -a
# Linux ... 4.14.11-coreos #1 SMP Fri Jan 5 11:00:14 UTC 2018 x86_64 Linux

The kernel fix you mentioned is therefore in place.

@levischuckeats and @agoston: Could you alredy upgrade to a newer Linux version and did it solve your problem?

Doing an strace on the java process shows things like:

[pid    24] restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid    24] <... restart_syscall resumed> ) = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999399} <unfinished ...>
[pid    24] <... futex resumed> )       = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999473} <unfinished ...>
[pid    24] <... futex resumed> )       = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999553} <unfinished ...>
[pid    24] <... futex resumed> )       = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999402} <unfinished ...>
[pid    24] <... futex resumed> )       = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999687}) = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999498}) = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999564}) = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0
[pid    24] futex(0x7f92c42ee678, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=49999496} <unfinished ...>
[pid    24] <... futex resumed> )       = -1 ETIMEDOUT (Operation timed out)
[pid    24] futex(0x7f92c42ee628, FUTEX_WAKE_PRIVATE, 1) = 0

(The full strace output would be available if it'll help you.)

Now the hard question: could this still be a bug in the Linux kernel? 🤔
Any tips where this could be discussed as well?

[levischuckeats]

Hello @ractive

We have since upgraded ubuntu and the kernel and have not encountered these problems since.

[ben-manes]

Its worth noting that people who have observed this deadlock, have also seen it on other caching libraries. That hints towards it being the kernel bug since we cannot reproduce it elsewhere.

@agoston had mentioned switching to Caffeine from Ehcache since he had observed a deadlock there.

Some Gerrit users have switched from Guava due to observing an unexplainable deadlock there. They also saw it occur in Caffeine at a lower rate. I had mentioned the kernel bug and, while Redhat had claimed the patch was in place, they were planning on upgrading regardless.

I am suspicious mostly because while I may have made mistakes, it is odd that other mature libraries have deadlocks for those users too. Those being recent too, despite the development of those libraries being stagnant. I was not able to reproduce it locally (mac) and didn't have the time to spin up a Linux box to test with. That would be our next step if you're believe a kernel update won't fix it.

[ractive]

Good to hear that your issue has been resolved by upgrading the kernel, @levischuckeats!

The deadlock occurs with the following scenario:
We use hystrix to do requests to another web service inside hystrix's threadpool like:

public class ExampleClient {
    private Cache<String, Something> cache;
    private RestTemplate restTemplate; // spring's rest client

    @HystrixCommand(fallbackMethod="emptyReply")
    public Something doSomething(String someKey) {
        ....
        return cache.get(someKey, key -> restTemplate.getForObject("http://example.com.?id=" + key, Something.class);
    }

    public Something emptyReply() {
        return new Something();
    }
}  

Now when the calls to the example.com rest service get slow or timeout, the number of used threads in the hystrix thread pool pretty quickly jumps to the max pool size and threads are never released anymore, all hanging with exactly the same stacktrace as initially described in this issue here.

Here's the copmlete stacktrace we have from our threads:

"hystrix-ExampleClient-29" #101 daemon prio=5 os_prio=0 tid=0x00007fca0c607000 nid=0x71 waiting on condition [0x00007fc9a37f5000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c393ebf8> (a com.github.benmanes.caffeine.cache.NonReentrantLock$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at com.github.benmanes.caffeine.cache.NonReentrantLock$Sync.lock(NonReentrantLock.java:315)
    at com.github.benmanes.caffeine.cache.NonReentrantLock.lock(NonReentrantLock.java:78)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:994)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:914)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2027)
    at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:1954)
    at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:113)
    at com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:54)
    at com.example.ExampleClient.doSomething(ExampleClient.java:110)
    at sun.reflect.GeneratedMethodAccessor59.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.execute(MethodExecutionAction.java:116)
    at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.executeWithArgs(MethodExecutionAction.java:93)
    at com.netflix.hystrix.contrib.javanica.command.MethodExecutionAction.execute(MethodExecutionAction.java:78)
    at com.netflix.hystrix.contrib.javanica.command.GenericCommand$1.execute(GenericCommand.java:48)
    at com.netflix.hystrix.contrib.javanica.command.AbstractHystrixCommand.process(AbstractHystrixCommand.java:145)
    at com.netflix.hystrix.contrib.javanica.command.GenericCommand.run(GenericCommand.java:45)
    at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:302)
    at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:298)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:46)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10151)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:51)
    at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35)
    at rx.Observable.unsafeSubscribe(Observable.java:10151)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
    at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
    at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
    at rx.Observable.unsafeSubscribe(Observable.java:10151)
    at rx.internal.operators.OperatorSubscribeOn$1.call(OperatorSubscribeOn.java:94)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:56)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:47)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction.call(HystrixContexSchedulerAction.java:69)
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:748)

Not sure how hystrix comes into play here as well as it defines its own timeouts for the calls to the doSomething method etc.

Maybe this setup gives you other ideas why these deadlocks can occur...
We will try to reproduce this issue with a stripped down version of our app running on pure docker. I'll keep you posted.

[levischuckeats]

Your stack trace has the same key indicators that our crashes had.
It gets locked during cleanup
com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:994)

[ractive]

Yes, exactly.

[ben-manes]

It could help us narrow this down if you upgrade the dependency. The NonReentrantLock was removed as a defunct optimization, given other prior work, so a normal ReentrantLock is used. That at least reduces the surface area of my code that could be wrong. I have not been notified with a deadlock using that lock, so maybe that helps resolve this case?

[ractive]

Ok. We'll update the caffeine version and see what happens.

[agoston]

I am still under the impression that this is caused by the JVM bugs outlined in https://github.com/ben-manes/caffeine/issues/203#issuecomment-344542136

The fact that this happens sporadically under heavy contention makes it very hard to pinpoint.

I can confirm that ehcache 2.10 had the exact same issue, that was the point to begin migration to caffeine.

For us, with the synchronized() hack at the contention points, it works OK. Note that we have not seen this issue at any other place besides that one despite caffeine being used in hundreds of other places and purposes.

[ractive]

It happened also with the latest caffeine version:

"hystrix-AutosuggestClient-29" #131 daemon prio=5 os_prio=0 tid=0x00007f510c286800 nid=0x8f waiting on condition [0x00007f5090cca000]
   java.lang.Thread.State: WAITING (parking)
  at sun.misc.Unsafe.park(Native Method)
  - parking to wait for  <0x00000000c3c0abd8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
  at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
  at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1106)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1027)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2104)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:2020)
  at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:112)
  at com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:54)
  ...

We again will see if we can create a sample app that shows that.

[ben-manes]

Sorry to hear that. A failing test case would be wonderful if you can produce one. When I review the lock usage it explicitly follows the idiom lock, try.., finally.. unlock. We may need a JDK engineer if we have a failing test, since I can't eyeball the problem (but more eyes the better, so take a look).

[ben-manes]

@ractive any luck reproducing this? Sorry that I cannot be of much help.

[ractive]

Honestly i didn't have time to try to create a project to reproduce this. :-/
But the good news is that we didn't have any occurence of the deadlock anymore for 10 days. So the new version of caffeine seems at least more resistant to this error then the older one... 👍

[agoston]

Just happened again for us with caffeine 2.6.2.

at sun.misc.Unsafe.park(Native Method) 
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) 
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) 
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) 
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) 
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) 
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) 
at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1106) 
at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1027) 
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1664) 
at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1612) 
at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:64)

[ben-manes]

I’m not sure how to help, unfortunately. What kernel and jdk?

[agoston]

Nah, I know there's not much we can do, this is more to keep track for other unfortunate souls.
I still believe this is a JVM/kernel bug, not a caffeine bug.

For us, java version is 1.8.0_161 and the kernel version is 2.6.32-696.23.1.el6.x86_64.

[johnou]

@agoston what JVM options? Are you monitoring your heap? Could an OOM have occurred?

[agoston]

JVM options are really super complex (a CMS GC tuned to the teeth), but I'm assured there was no OOM situation.

[johnou]

Can you dump the JVM options here so we can run the Stresser with them?

[johnshawn-david]

I still have this problem. caffeine version 2.8.6. java version 1.8.0_201 and kernel version is Linux 3.10.0-862.14.4.el7.x86_64 x86_64

"XNIO-1 task-11" #1460 prio=5 os_prio=0 tid=0x00007fd2fc001800 nid=0x5ab waiting on condition [0x00007fd25e53a000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000c361ca80> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.performCleanUp(BoundedLocalCache.java:1445)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.afterWrite(BoundedLocalCache.java:1366)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:2007)
        at com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:1955)
        at com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:130)

[ben-manes]

Sorry, that isn't enough details. You probably need to send all of the stack traces to see the other threads blocked

[ben-manes]

The afterWrite is a hint though. It looks like the write buffer exceeded capacity (128 * NCPUs) which is quite generous. This means a lot of write operations are queued up and not being run. The cache then blocks writes on the eviction lock in order to deprioritize writes and have them help clean up. This indicates some starvation so that the owner of this lock is never progressing and everything is blocked.

Do you have a thread performing a compute? Maybe you have a live-lock on eviction due to recursive computations, so it cannot remove the entry.

[johnshawn-david]

Thank you for your reply. Indeed in my application, a lot of write operations exist，but they were blocked, and I had not find the owner of this lock. I use jstack export thread info.
thread stack.

[ben-manes]

The ForkJoinWorkerThread is blocked waiting on the lock, as are all of the other threads. I don't see any ConcurrentHashMap operations, anything performing work under the lock, etc. My guess is it is a JVM / Linux / HW bug like this one, where the unlock signal is never communicated. That is too low level for me to debug...

Are you using OpenJDK or a custom distribution? If so, then you might ask them since it might be a bug there.

[johnshawn-david]

Thanks. I'm using oracle jdk. Here is my jdk version:

java version "1.8.0_201"
Java(TM) SE Runtime Environment (build 1.8.0_201-b09)
Java HotSpot(TM) 64-Bit Server VM (build 25.201-b09, mixed mode)

[ben-manes]

hmm.. then I really don't know. I'm sorry, but there is not much to go on...

You could try using Caffeine.executor(Runnable::run) to see if that helps. It will perform the maintenance work on the caller threads.

[johnshawn-david]

OK. Thank you for your advice, I will have a try.

[ben-manes]

Is that Linux kernel version old enough to be subject to the lost wake up bug mentioned in this thread? It looks like it and if so, you need to upgrade the OS

[ben-manes]

June 2013 for 3.10 and the bug is confirmed in 3.19 which is from February 2015. I don’t know much but you should try to use a modern distribution

[johnshawn-david]

Yes, I'm using centos 7, and it's kenel version is Linux 3.10.0, maybe it is the bug from the OS. I think there must be some case in my code trigger this bug. In general, use ReentrantLock can not trigger this bug. I try if I can reproduce this case. I guess maybe use synchronize(string.intern) and inside use Caffeine.put operate trigger this. If I can not reproduce, I will try upgrade the OS.

[johnshawn-david]

when I change to use Guava cache，the problem still exist. It should not be Caffeine's problem.

"DubboServerHandler-10.198.65.150:20880-thread-957" #1243 daemon prio=5 os_prio=0 tid=0x000000000195f800 nid=0x4d0 waiting on condition [0x00007f2e53f6a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c2abca68> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at com.google.common.cache.LocalCache$Segment.put(LocalCache.java:2771)
    at com.google.common.cache.LocalCache.put(LocalCache.java:4192)
    at com.google.common.cache.LocalCache$LocalManualCache.put(LocalCache.java:4876)

All threads waiting for the lock, but I can not find any thread hold the lock

[ben-manes]

Yes, this is what Gerrit also experienced with either library. I don’t know but it’s come up multiple times with different implementations and nothing in the code. There is some hardware/ OS / JVM bug causing havoc.

[johnshawn-david]

Yes, this is what Gerrit also experienced with either library. I don’t know but it’s come up multiple times with different implementations and nothing in the code. There is some hardware/ OS / JVM bug causing havoc.

In my case，I think this problem was caused by thread StackOverflowError. When this problem happened, I dumped the thread stack info and the heap info. In the heap I found the following phenomenon: (now I'm using guava, same as caffeine):

I searched in the log, and this thread had throwed StackOverflowError because of recursive operations:

2021-04-22 10:02:02.823 ERROR 1 --- [XNIO-1 task-2] com.li.dm.web.aop.LogAspect :

java.lang.StackOverflowError: null
    at com.google.common.cache.LocalCache$Segment.runLockedCleanup(LocalCache.java:3455)
    at com.google.common.cache.LocalCache$Segment.cleanUp(LocalCache.java:3444)
    at com.google.common.cache.LocalCache$Segment.postReadCleanup(LocalCache.java:3422)
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2078)
    at com.google.common.cache.LocalCache.getIfPresent(LocalCache.java:3967)
    at com.google.common.cache.LocalCache$LocalManualCache.getIfPresent(LocalCache.java:4853)
    at com.li.dm.service.service.impl.DialogCacheHandler.getKeyword(DialogCacheHandler.java:114)
    at com.li.dm.service.service.impl.KeywordMatcher.findKeywords(KeywordMatcher.java:95)
    at com.li.dm.service.service.impl.KeywordMatcher.matchKeyword(KeywordMatcher.java:61)
    at com.li.dm.service.service.impl.KeywordMatcher.matchKeyword(KeywordMatcher.java:56)

The thread was a thread in a threadpool. So I guess this was caused by thread StackOverflowError, because of this error, the thread exited without unlock, so the state for the reentrantLock was always 1, no chance for reset to 0. Then other threads operated the cache, exec lock(), and blocked.

[ben-manes]

Good find! Maybe this will help @kentwang929 who recently had a similar problem.

[kentwang929]

interesting, we also do observe StackOverFlow in our logs. good direction to debug, thanks!

[ben-manes]

fyi, I believe JEP-270 should have resolved that but it is Java 9 onward.

[kentwang929]

We are on java 14. This might be our code issue when the query is too large.