I've been getting a lot of TimeoutExceptions when the method Cache#get() is called. My cluster is set up as below:
0. The cluster runs on JBoss Cache 3.1.0 GA. The locking scheme is MVCC. The isolation level is READ_COMMITTED.
1. Two nodes, N1, and N2. Each node is a different machine. Each node has a cache instance.
2. The node N1 only reads from cache. If it doesn't find an entry from its local cache, it will read from N2 via a ClusteredCacheLoader. The ClusteredCacheLoader is asynchronous, but its serialization thread pool size is 0 (it would not work otherwise for some reason)
3. The node N2 both reads from and writes to its cache.
If I understand it correctly, a read operation doesn't not aquire a lock, let alone a write-lock. So, why would I get many TimeoutExceptions when Cache#get() was called, as the stack trace shows? Could anyone please let me what possibly could cause this problem?
Another interesting thing is, this problem was not seen during peak load. It happened when load was really low as if it would only happen after the system has been running for a while.
org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/parentNode/key] after [20000] milliseconds for requestor [Thread[pool-1-thread-37,5,main]]! Lock held by [null]
at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:157)
at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodeForWriting(MVCCNodeHelper.java:252)
at org.jboss.cache.mvcc.MVCCNodeHelper.wrapNodeForWriting(MVCCNodeHelper.java:184)
at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:300)
at org.jboss.cache.interceptors.CacheLoaderInterceptor.visitGetKeyValueCommand(CacheLoaderInterceptor.java:165)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:301)
at org.jboss.cache.interceptors.TxInterceptor.handleDefault(TxInterceptor.java:283)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:77)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.InterceptorChain.invoke(InterceptorChain.java:287)
at org.jboss.cache.invocation.CacheInvocationDelegate.get(CacheInvocationDelegate.java:444)
I also noticed quite many RejectedExceptions when there were many TimeoutExceptions. Are they somehow correlated?
java.util.concurrent.RejectedExecutionException
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:1759)
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:767)
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:658)
at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:92)
at org.jboss.cache.marshall.CommandAwareRpcDispatcher.invokeRemoteCommands(CommandAwareRpcDispatcher.java:206)
at org.jboss.cache.RPCManagerImpl.callRemoteMethods(RPCManagerImpl.java:748)
at org.jboss.cache.loader.ClusteredCacheLoader.callRemote(ClusteredCacheLoader.java:135)
at org.jboss.cache.loader.ClusteredCacheLoader.get0(ClusteredCacheLoader.java:195)
at org.jboss.cache.loader.ClusteredCacheLoader.get(ClusteredCacheLoader.java:182)
at org.jboss.cache.loader.ChainingCacheLoader.get(ChainingCacheLoader.java:111)
at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadData(CacheLoaderInterceptor.java:496)
at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:315)
at org.jboss.cache.interceptors.CacheLoaderInterceptor.visitGetKeyValueCommand(CacheLoaderInterceptor.java:165)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:131)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.TxInterceptor.attachGtxAndPassUpChain(TxInterceptor.java:301)
at org.jboss.cache.interceptors.TxInterceptor.handleDefault(TxInterceptor.java:283)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:77)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:116)
at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:178)
at org.jboss.cache.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:130)
at org.jboss.cache.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:110)
at org.jboss.cache.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:97)
at org.jboss.cache.interceptors.InterceptorChain.invoke(InterceptorChain.java:287)
at org.jboss.cache.invocation.CacheInvocationDelegate.get(CacheInvocationDelegate.java:444)
Thanks,
Yong