redisson: Cache ops taking too long

Currently i’m using Redisson 2.7.4 as JCache Provider, and some cache operations are taking a long time to execute, as can be seen in the log below:

2017-06-05 11:44:18.103 WARN  [com.contaazul.cache.cdi.interceptor.CacheResultInterceptor] (http-executor-threads - 89) Cache result for CompanyDemoFindService.find took 1669045 milliseconds

in some cases it takes ~30 minutes

Taking a thread dump I noticed that all EJB async threads (and some http-executor threads too) were in the same state, generating a huge queue in the async thread pool:

Thread dump for some threads (Complete thread dump can be downloaded here):

2017-06-05 11:03:55

"EJB async - 2" - Thread t@1214
   java.lang.Thread.State: TIMED_WAITING
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for <b485fd6> (a java.util.concurrent.Semaphore$NonfairSync)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1033)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1326)
	at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:414)
	at org.redisson.RedissonLock.lockInterruptibly(RedissonLock.java:133)
	at org.redisson.RedissonLock.lock(RedissonLock.java:99)
	at org.redisson.jcache.JCache.getLockedLock(JCache.java:746)
	at org.redisson.jcache.JCache.get(JCache.java:194)
	at com.contaazul.cache.FailSafeCache.get(FailSafeCache.java:21)
	at org.jsr107.ri.annotations.AbstractCacheResultInterceptor.cacheResult(AbstractCacheResultInterceptor.java:71)
	at com.contaazul.cache.cdi.interceptor.CacheResultInterceptor.cacheResult(CacheResultInterceptor.java:28)
	at sun.reflect.GeneratedMethodAccessor141.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.weld.interceptor.proxy.SimpleMethodInvocation.invoke(SimpleMethodInvocation.java:30)
	at org.jboss.weld.interceptor.proxy.SimpleInterceptionChain.invokeNextInterceptor(SimpleInterceptionChain.java:69)
	at org.jboss.weld.bean.InterceptorImpl.intercept(InterceptorImpl.java:92)
	at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:71)
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:72)
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:84)
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:97)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:73)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:259)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.notSupported(CMTTxInterceptor.java:323)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:236)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:185)
	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73)
	at com.contaazul.company.CompanyDemoFindService$$$view659.find(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor146.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.weld.util.reflection.SecureReflections$13.work(SecureReflections.java:267)
	at org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52)
	at org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137)
	at org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:263)
	at org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:115)
	at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56)
	at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105)
	at com.contaazul.company.CompanyDemoFindService$Proxy$_$$_Weld$Proxy$.find(CompanyDemoFindService$Proxy$_$$_Weld$Proxy$.java)
	at com.contaazul.fanout.ApplicationTrackService.resolveOrigin(ApplicationTrackService.java:161)
	at com.contaazul.fanout.ApplicationTrackService.getContentDTO(ApplicationTrackService.java:131)
	at com.contaazul.fanout.ApplicationTrackService.sendTrack(ApplicationTrackService.java:104)
	at com.contaazul.fanout.ApplicationTrackService.sendTrackOperation(ApplicationTrackService.java:72)
	at com.contaazul.fanout.ApplicationTrackService.track(ApplicationTrackService.java:48)
	at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374)
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:86)
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:97)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:93)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:259)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.notSupported(CMTTxInterceptor.java:323)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:236)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:185)
	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
	at org.jboss.as.ejb3.component.interceptors.AsyncFutureInterceptorFactory$1$1.runInvocation(AsyncFutureInterceptorFactory.java:89)
	at org.jboss.as.ejb3.component.interceptors.AsyncInvocationTask.run(AsyncInvocationTask.java:73)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)
	at org.jboss.threads.JBossThread.run(JBossThread.java:122)

   Locked ownable synchronizers:
	- locked <f75019a> (a java.util.concurrent.ThreadPoolExecutor$Worker)


"redisson-3-9" - Thread t@1416
   java.lang.Thread.State: WAITING
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for <2d3b7977> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None


"redisson-netty-1-9" - Thread t@1297
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
	at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
	at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
	- locked <7ed0d3e3> (a io.netty.channel.nio.SelectedSelectionKeySet)
	- locked <130940b7> (a java.util.Collections$UnmodifiableSet)
	- locked <4eab503d> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
	at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:746)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:391)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None

it looks like that is a lock issue, but i don’t know how to solve it.