3 Replies Latest reply on May 11, 2006 1:57 AM by Ben Wang

    JBoss throwing org.jboss.cache.lock.TimeoutException: read l

    Amarish Khopkar Newbie

      Hi guys,

      We have deployed JBoss 4.0.3 SP1 successfully about a month ago with 2 servers that are using the Tomcat Web clustering only (we are using an .ear file and calling local ejb3 from the .war files so the back end is not clustered).

      For about a month, we had low load applications on this and it didn't have any problems.

      About 2 days ago we migrated our high load applications to this cluster, and started noticing major problems. The applications are completely hanging since we are using synchronous replication, and they are basically timing out and we are having to constantly restart the servers and drop users by doing this, and after a period of time it happens again and we have to restart again.

      We are using REPL_SYNC, and we do not have sticky session enabled so at any point any request can hit either box as directed by the load balancer, and we are relying on jboss clustering for the session replication entirely.

      I'm noticing a session read timeout problem in the logs. Any input would be appreciated. Here's the exception that it keeps throwing in the log:

      10:32:12,312 ERROR [IdentityLock] read lock for /JSESSION/localhost/ebol/gzJ2Abf3q7AcEOGdefAMFQ** could not be acquired by Thread[http-8081-Processor35,5,jboss] after 15000 ms. Locks: Read lock owners: []
      Write lock owner: <myserver135:33077>:22862
      , lock info: write owner=<myserver135:33077>:22862 (activeReaders=0, activeWriter=Thread[http-8081-Processor35,5,jboss], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      10:32:12,313 INFO [STDOUT] org.jboss.cache.lock.TimeoutException: read lock for /JSESSION/localhost/myapp/gzJ2Abf3q7AcEOGdefAMFQ** could not be acquired by Thread[http-8081-Processor35,5,jboss] after 15000 ms. Locks: Read lock owners: []
      Write lock owner: <myserver135:33077>:22862
      , lock info: write owner=<myserver135:33077>:22862 (activeReaders=0, activeWriter=Thread[http-8081-Processor35,5,jboss], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)
      10:32:12,313 INFO [STDOUT] at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:213)
      10:32:12,313 INFO [STDOUT] at org.jboss.cache.Node.acquireReadLock(Node.java:501)
      10:32:12,313 INFO [STDOUT] at org.jboss.cache.Node.acquire(Node.java:473)
      10:32:12,313 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.lock(LockInterceptor.java:245)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.invoke(LockInterceptor.java:159)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:41)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:35)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:41)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.ReplicationInterceptor.invoke(ReplicationInterceptor.java:54)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:3116)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.TreeCache.get(TreeCache.java:1571)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.TreeCache.get(TreeCache.java:1555)
      10:32:12,314 INFO [STDOUT] at sun.reflect.GeneratedMethodAccessor216.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at java.lang.reflect.Method.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)
      10:32:12,314 INFO [STDOUT] at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:176)
      10:32:12,314 INFO [STDOUT] at $Proxy100.get(Unknown Source)
      10:32:12,314 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService._get(JBossCacheService.java:402)
      10:32:12,314 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.nodeDirty(JBossCacheService.java:679)
      10:32:12,314 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.nodeModified(JBossCacheService.java:670)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.TreeCache.notifyNodeModified(TreeCache.java:3187)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.TreeCache._put(TreeCache.java:2420)
      10:32:12,314 INFO [STDOUT] at sun.reflect.GeneratedMethodAccessor234.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at java.lang.reflect.Method.invoke(Unknown Source)
      10:32:12,314 INFO [STDOUT] at org.jgroups.blocks.MethodCall.invoke(MethodCall.java:236)
      10:32:12,314 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.rollback(LockInterceptor.java:343)
      10:32:12,315 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor.access$200(LockInterceptor.java:25)
      10:32:12,315 INFO [STDOUT] at org.jboss.cache.interceptors.LockInterceptor$SynchronizationHandler.afterCompletion(LockInterceptor.java:425)
      10:32:12,315 INFO [STDOUT] at org.jboss.cache.interceptors.OrderedSynchronizationHandler.afterCompletion(OrderedSynchronizationHandler.java:80)
      10:32:12,315 INFO [STDOUT] at org.jboss.tm.TransactionImpl.doAfterCompletion(TransactionImpl.java:1508)
      10:32:12,315 INFO [STDOUT] at org.jboss.tm.TransactionImpl.completeTransaction(TransactionImpl.java:1180)
      10:32:12,315 INFO [STDOUT] at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:351)
      10:32:12,315 INFO [STDOUT] at org.jboss.tm.TxManager.commit(TxManager.java:224)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.endTransaction(JBossCacheManager.java:636)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.processSessionRepl(JBossCacheManager.java:627)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.storeSession(JBossCacheManager.java:375)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:38)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91)
      10:32:12,315 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
      10:32:12,315 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
      10:32:12,315 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
      10:32:12,315 INFO [STDOUT] at org.apache.catalina.valves.FastCommonAccessLogValve.invoke(FastCommonAccessLogValve.java:481)
      10:32:12,315 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
      10:32:12,315 INFO [STDOUT] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
      10:32:12,315 INFO [STDOUT] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
      10:32:12,315 INFO [STDOUT] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
      10:32:12,315 INFO [STDOUT] at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
      10:32:12,315 INFO [STDOUT] at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
      10:32:12,315 INFO [STDOUT] at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
      10:32:12,315 INFO [STDOUT] at java.lang.Thread.run(Unknown Source)

        • 1. Re: JBoss throwing org.jboss.cache.lock.TimeoutException: re
          Brian Stansberry Master

          This stack trace looks like what you'd see from http://jira.jboss.com/jira/browse/JBCACHE-359. Can you try upgrading to JBoss Cache 1.2.4.SP2?

          • 2. Re: JBoss throwing org.jboss.cache.lock.TimeoutException: re
            Amarish Khopkar Newbie

            No luck.

            I tried the new jboss-cache as you suggested and got this exception. Also it would hang the second server and prevent it from coming up.

            Any clue?

            14:53:41,840 INFO [TreeCache] interceptor chain is:
            class org.jboss.cache.interceptors.CallInterceptor
            class org.jboss.cache.interceptors.LockInterceptor
            class org.jboss.cache.interceptors.UnlockInterceptor
            class org.jboss.cache.interceptors.ReplicationInterceptor
            14:53:41,840 INFO [TreeCache] cache mode is REPL_SYNC
            14:53:43,873 INFO [TreeCache] viewAccepted(): new members: [adams236:32791, adams235:32797]
            14:53:43,878 INFO [TreeCache] received the state (size=154 bytes)
            14:53:43,879 ERROR [TreeCache] failed unserializing state
            java.io.OptionalDataException
            at java.io.ObjectInputStream.readObject0(Unknown Source)
            at java.io.ObjectInputStream.readObject(Unknown Source)
            at org.jgroups.util.Util.objectFromByteBuffer(Util.java:46)
            at org.jboss.cache.TreeCache$MessageListenerAdaptor._setState(TreeCache.java:2904)
            at org.jboss.cache.TreeCache$MessageListenerAdaptor.setState(TreeCache.java:2871)
            at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.passUp(MessageDispatcher.java:614)
            at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:331)
            at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.handleUp(MessageDispatcher.java:722)
            at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.access$300(MessageDispatcher.java:554)
            at org.jgroups.blocks.MessageDispatcher$1.run(MessageDispatcher.java:691)
            at java.lang.Thread.run(Unknown Source)
            14:53:43,879 INFO [TreeCache] state was retrieved successfully (in 6 milliseconds)
            14:53:44,315 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-ha-local-jdbc.rar
            14:53:44,420 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-ha-xa-jdbc.rar

            • 3. Re: JBoss throwing org.jboss.cache.lock.TimeoutException: re
              Ben Wang Master

              Did you upgrade JBossCache in both servers? Can you also upgrade the jgroups version that came with it?