Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-3946

TimeoutException: Unable to acquire lock after 15 seconds in repl-async stress tests

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Critical Critical
    • 7.1.0.DR12
    • 7.0.0.ER7
    • Clustering
    • None

      Scenarios:
      stress-ejbservlet-repl-async
      stress-session-repl-async

      When the number of clients reaches 1600, servers start logging TimeoutExceptions (approx 500 occurrences in each server), which definitely results in client getting 500:

      [JBossINF] [0m[31m08:44:32,765 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-126) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key pL7oPBPQV9X21ErUIku54-wkPMvaHTWwbknWx4OW and requestor GlobalTransaction:<perf19>:1121985:local. Lock is held by GlobalTransaction:<perf19>:1120208:local
      [JBossINF] 	at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:236)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAndRecord(AbstractLockingInterceptor.java:190)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockKey(AbstractTxLockingInterceptor.java:192)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockOrRegisterBackupLock(AbstractTxLockingInterceptor.java:113)
      [JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataReadCommand(PessimisticLockingInterceptor.java:70)
      [JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:77)
      [JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
      [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
      [JBossINF] 	at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:345)
      [JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:330)
      [JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
      [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
      [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
      [JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
      [JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
      [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
      [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitReadCommand(StateTransferInterceptor.java:176)
      [JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitGetKeyValueCommand(StateTransferInterceptor.java:153)
      [JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
      [JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
      [JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:107)
      [JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:76)
      [JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
      [JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)
      [JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)
      [JBossINF] 	at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:411)
      [JBossINF] 	at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:443)
      [JBossINF] 	at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:286)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.getValue(InfinispanSessionMetaDataFactory.java:72)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:62)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionMetaDataFactory.findValue(InfinispanSessionMetaDataFactory.java:36)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:61)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionFactory.findValue(InfinispanSessionFactory.java:40)
      [JBossINF] 	at org.wildfly.clustering.web.infinispan.session.InfinispanSessionManager.findSession(InfinispanSessionManager.java:235)
      [JBossINF] 	at org.wildfly.clustering.web.undertow.session.DistributableSessionManager.getSession(DistributableSessionManager.java:148)
      [JBossINF] 	at io.undertow.servlet.spec.ServletContextImpl.getSession(ServletContextImpl.java:726)
      [JBossINF] 	at io.undertow.servlet.spec.HttpServletRequestImpl.getSession(HttpServletRequestImpl.java:370)
      [JBossINF] 	at org.jboss.weld.servlet.SessionHolder.requestInitialized(SessionHolder.java:47)
      [JBossINF] 	at org.jboss.weld.servlet.HttpContextLifecycle.requestInitialized(HttpContextLifecycle.java:234)
      [JBossINF] 	at org.jboss.weld.servlet.WeldInitialListener.requestInitialized(WeldInitialListener.java:152)
      [JBossINF] 	at io.undertow.servlet.core.ApplicationListeners.requestInitialized(ApplicationListeners.java:245)
      [JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:284)
      [JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:264)
      [JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
      [JBossINF] 	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:175)
      [JBossINF] 	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
      [JBossINF] 	at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:792)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      [JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      [JBossINF] 	at java.lang.Thread.run(Thread.java:745)
      

      Client:

      2016/03/21 08:41:45:760 EDT [WARN ][Runner - 244] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>>
              org.jboss.smartfrog.loaddriver.RequestProcessingException: Invalid response code: 500 Content: <html><head><title>Error</title></head><body>Internal Server Error</body></html>
      	at org.jboss.smartfrog.loaddriver.http.HttpRequestProcessorFactoryImpl$HttpRequestProcessor.processRequest(HttpRequestProcessorFactoryImpl.java:163)
      	at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52)
      	at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:103)
      	at java.lang.Thread.run(Thread.java:745)
      

      stress-ejbservlet-repl-async
      Server link: http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-stress-ejbservlet-repl-async/12/console-perf19/
      Client link: http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-stress-ejbservlet-repl-async/12/console-perf23/

      stress-session-repl-async
      Server link: http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-stress-session-repl-async/9/console-perf18/
      Client link: http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-7x-stress-session-repl-async/9/console-perf23/

      Performance report:
      http://download.eng.brq.redhat.com/scratch/mvinkler/reports/2016-03-24_11-27-03/stress.html

      The issue looks very similar to JBEAP-2273.

              rhn-engineering-rhusar Radoslav Husar
              mvinkler1@redhat.com Michal Vinkler
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Created:
                Updated:
                Resolved: