so we are using Guava v18. We are going a lot of thread with this content:
"catalina-exec-ajp2" daemon prio=10 tid=0x00007fb45c001800 nid=0x18aa waiting on condition [0x00007fb435151000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000075ff0cfe8> (a com.google.common.util.concurrent.AbstractFuture$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285)
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:137)
at com.google.common.cache.LocalCache$LoadingValueReference.waitForValue(LocalCache.java:3557)
at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(LocalCache.java:2302)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2191)
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)
at com.xxx.yyy.repository.cache.acl.guava.GuavaCacheWrapper.get(GuavaCacheWrapper.java:21)
at com.xxx.yyy.repository.cache.CachedCpaRepository.findAll(CachedCpaRepository.java:32)
Our guava configuration is:
@SuppressWarnings("unchecked")
@Override
protected <K, R> CacheWrapper<K, R> newCacheConfiguration(Fetcher fetcher, String cacheName, int maxElementsInMemory,
int timeToIdleSeconds, int timeToLiveSeconds)
{
Cache existingCache = manager.getCache(cacheName);
CacheWrapper<K, R> cache;
if(null == existingCache)
{
cache = new GuavaCacheWrapper<>(CacheBuilder.newBuilder()
.maximumSize(maxElementsInMemory)
.expireAfterAccess(timeToIdleSeconds, SECONDS)
.refreshAfterWrite(timeToLiveSeconds, SECONDS)
.recordStats()
.build( CacheLoader.asyncReloading(fetcher.getAs(CacheLoader.class), executors)));
manager.addCache(cacheName, cache);
}
else
{
cache = (CacheWrapper<K, R>) ((GuavaCache) existingCache).getNativaGuavaCache();
}
return cache;
}
I'm a bit clueless on what I could check to see what's generating the problem. Could you suggest what I can check?
If you have blocking gets on a LoadingCache, it means you're loading the value for the same key from multiple threads: the first thread actually loads the value, and the next threads wait for that load to complete.
Maybe you have a small number of keys and processing the value is a costly operation? You could log the keys you're trying to load, and the duration of the loading.
Update
The threads doing the actual loading are the ones calling the CacheLoader, but you can't find which corresponds to which waiting thread from the thread dump (if there are multiple threads loading).
I created a test to reproduce the situation:
public class ExpensiveCache {
private final LoadingCache<String, String> cache = CacheBuilder.newBuilder().build(new ExpensiveCacheLoader());
public static void main(String... args) {
new ExpensiveCache().run();
}
private void run() {
// Start 2 threads concurrently accessing the same key in the cache
for (int i = 0; i < 2; i++) {
new Thread(() -> cache.getUnchecked("key")).start();
}
}
private static class ExpensiveCacheLoader extends CacheLoader<String, String> {
@Override
public String load(String key) throws Exception {
// Make the computation "expensive" by sleeping for 60s
Thread.sleep(60_000);
return key;
}
}
}
You indeed can't find the id of the condition anywhere else in the thread dump:
"Thread-2" #12 prio=5 os_prio=31 tid=0x00007fbb6384e000 nid=0x5703 waiting on condition [0x00000001291c5000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076b183208> (a com.google.common.util.concurrent.AbstractFuture$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.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285)
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:137)
at com.google.common.cache.LocalCache$LoadingValueReference.waitForValue(LocalCache.java:3557)
at com.google.common.cache.LocalCache$Segment.waitForLoadingValue(LocalCache.java:2302)
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2289)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)
at io.github.fpavageau.ExpensiveCache.lambda$run$0(ExpensiveCache.java:16)
at io.github.fpavageau.ExpensiveCache$$Lambda$1/1108411398.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)
"Thread-1" #11 prio=5 os_prio=31 tid=0x00007fbb6384d000 nid=0x5503 waiting on condition [0x00000001290c2000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at io.github.fpavageau.ExpensiveCache$ExpensiveCacheLoader.load(ExpensiveCache.java:23)
at io.github.fpavageau.ExpensiveCache$ExpensiveCacheLoader.load(ExpensiveCache.java:20)
at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)
at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)
at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)
- locked <0x000000076b199a50> (a com.google.common.cache.LocalCache$StrongEntry)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)
at io.github.fpavageau.ExpensiveCache.lambda$run$0(ExpensiveCache.java:16)
at io.github.fpavageau.ExpensiveCache$$Lambda$1/1108411398.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)