1 Reply Latest reply on Jun 16, 2009 6:34 PM by g9yuayon

    lots of TimeoutException

      Hi,

      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 with synchronous replication.
      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, and how I could solve it?

      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)


        • 1. Re: lots of TimeoutException

          It turned out I misconfigured the backend server, N2. I added a ClusteredCacheLoader to N2. Therefore, N2 would send a request to the server N1 when a cache entry didn't exist or was evicted. However, since N1 was the server that initiated requests using ClusteredCacheLoader, deadlocks ensued when timing was right.