1 Reply Latest reply on Jun 12, 2012 1:45 AM by bradleydouglas

    ConcurrentAccessTimeoutException ... could not obtain lock within 5MINUTES

    bradleydouglas

      Hi all,

       

      We've just finished migrating an app in AS 6.1 and Seam 2.2.2 (I know there will be be folks out there that just say upgrade to 7 at this point, but when we started the migration 7 was still .0, so I need to get a work around for 6.1).

       

      When we did our first testing, it all looked good, but when the site came under moderate load, we started getting reports of really poor performance.  Looking through the logs, I can see errors where try to aquire a lock (guarding against re-entrant code I think) is timing out.  Here is the error full error details:

       

      2012-05-30 14:57:07,047 SEVERE [facelets.viewhandler] (http-0.0.0.0-8080-4) Error Rendering View[/protected/admin/reservation/documentGeneration.xhtml]: javax.ejb.ConcurrentAccessTimeoutException: EJB 3.1 PFD2 4.8.5.5.1 concurrent access timeout on [advisedMethod=public java.lang.Boolean com.synyati.spurwing.reservation.documentation.action.DocumentGenerationActionBean.docGenInit(), unadvisedMethod=public java.lang.Boolean com.synyati.spurwing.reservation.documentation.action.DocumentGenerationActionBean.docGenInit(), metadata=[metaData={SessionInvocation={InvokedMethod=[type=MARSHALLEDvalue=com.synyati.spurwing.reservation.documentation.action.DocumentGenerationAction: com.synyati.spurwing.reservation.documentation.action.DocumentGenerationAction.docGenInit()]}}], targetObject=com.synyati.spurwing.reservation.documentation.action.DocumentGenerationActionBean@59f5d678, arguments=[Ljava.lang.Object;@2c7a0537] - could not obtain lock within 5MINUTES

          at org.jboss.ejb3.concurrency.aop.interceptor.ContainerManagedConcurrencyInterceptor.invoke(ContainerManagedConcurrencyInterceptor.java:176)

          at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.stateful.StatefulInstanceAssociationInterceptor.invoke(StatefulInstanceAssociationInterceptor.java:55)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.core.context.SessionInvocationContextAdapter.proceed(SessionInvocationContextAdapter.java:95)

          at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:223)

          at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.required(CMTTxInterceptor.java:353)

          at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invoke(CMTTxInterceptor.java:209)

          at org.jboss.ejb3.tx2.aop.CMTTxInterceptorWrapper.invoke(CMTTxInterceptorWrapper.java:52)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.security.RunAsSecurityInterceptorv2.invoke(RunAsSecurityInterceptorv2.java:94)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptorv2.invoke(RoleBasedAuthorizationInterceptorv2.java:201)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:182)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:41)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.core.context.CurrentInvocationContextInterceptor.invoke(CurrentInvocationContextInterceptor.java:47)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.interceptor.EJB3TCCLInterceptor.invoke(EJB3TCCLInterceptor.java:86)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.session.SessionSpecContainer.invoke(SessionSpecContainer.java:333)

          at org.jboss.ejb3.session.SessionSpecContainer.invoke(SessionSpecContainer.java:390)

          at sun.reflect.GeneratedMethodAccessor474.invoke(Unknown Source)

          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

          at java.lang.reflect.Method.invoke(Method.java:597)

          at org.jboss.ejb3.proxy.impl.handler.session.SessionLocalProxyInvocationHandler$LocalContainerInvocation.invokeTarget(SessionLocalProxyInvocationHandler.java:184)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)

          at org.jboss.ejb3.async.impl.interceptor.AsynchronousClientInterceptor.invoke(AsynchronousClientInterceptor.java:143)

          at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)

          at org.jboss.ejb3.proxy.impl.handler.session.SessionLocalProxyInvocationHandler$LocalInvokableContextHandler.invoke(SessionLocalProxyInvocationHandler.java:159)

          at $Proxy442.invoke(Unknown Source)

          at org.jboss.ejb3.proxy.impl.handler.session.SessionProxyInvocationHandlerBase.invoke(SessionProxyInvocationHandlerBase.java:185)

          at $Proxy378.docGenInit(Unknown Source)

          at sun.reflect.GeneratedMethodAccessor2097.invoke(Unknown Source)

          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

          at java.lang.reflect.Method.invoke(Method.java:597)

          at org.jboss.seam.util.Reflections.invoke(Reflections.java:22)

          at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32)

          at org.jboss.seam.intercept.ClientSideInterceptor$1.proceed(ClientSideInterceptor.java:76)

          at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56)

          at org.jboss.seam.ejb.RemoveInterceptor.aroundInvoke(RemoveInterceptor.java:43)

          at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68)

          at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107)

          at org.jboss.seam.intercept.ClientSideInterceptor.invoke(ClientSideInterceptor.java:54)

          at org.javassist.tmp.java.lang.Object_$$_javassist_seam_8.docGenInit(Object_$$_javassist_seam_8.java)

          at sun.reflect.GeneratedMethodAccessor2096.invoke(Unknown Source)

          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

          at java.lang.reflect.Method.invoke(Method.java:597)

          at org.jboss.seam.util.Reflections.invoke(Reflections.java:22)

          at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144)

          at org.jboss.seam.Component.callComponentMethod(Component.java:2275)

          at org.jboss.seam.Component.getInstanceFromFactory(Component.java:2101)

          at org.jboss.seam.Component.getInstance(Component.java:2014)

          at org.jboss.seam.Component.getInstance(Component.java:1986)

          at org.jboss.seam.Component.getInstance(Component.java:1980)

          at org.jboss.seam.Namespace.getComponentInstance(Namespace.java:55)

          at org.jboss.seam.Namespace.getComponentInstance(Namespace.java:50)

          at org.jboss.seam.el.SeamELResolver.resolveBase(SeamELResolver.java:148)

          at org.jboss.seam.el.SeamELResolver.getValue(SeamELResolver.java:51)

          at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:173)

          at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:200)

          at org.jboss.el.parser.AstIdentifier.getValue(AstIdentifier.java:44)

          at org.jboss.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:186)

          at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:71)

          at javax.faces.component.UIComponentBase.isRendered(UIComponentBase.java:393)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:924)

          at javax.faces.render.Renderer.encodeChildren(Renderer.java:148)

          at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:840)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:930)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:933)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:933)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:933)

          at javax.faces.component.UIComponent.encodeAll(UIComponent.java:933)

          at com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:592)

          at org.ajax4jsf.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:100)

          at org.ajax4jsf.application.AjaxViewHandler.renderView(AjaxViewHandler.java:176)

          at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:110)

          at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100)

          at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)

          at javax.faces.webapp.FacesServlet.service(FacesServlet.java:266)

          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:324)

          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:242)

          at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:530)

          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:274)

          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:242)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:83)

          at org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:90)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:45)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.web.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:42)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:73)

          at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:206)

          at org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:290)

          at org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:388)

          at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:515)

          at org.jboss.seam.web.Ajax4jsfFilter.doFilter(Ajax4jsfFilter.java:56)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.web.HotDeployFilter.doFilter(HotDeployFilter.java:53)

          at org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)

          at org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158)

          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:274)

          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:242)

          at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)

          at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)

          at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:181)

          at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:593)

          at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:88)

          at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:100)

          at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:159)

          at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)

          at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)

          at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

          at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:53)

          at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:362)

          at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877)

          at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:654)

          at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:951)

          at java.lang.Thread.run(Thread.java:662)

       

       

      It appears to me that the thread is trying to obtain a lock before calling a method on an instance of oen of our SFSBs (DocumentGenerationActionBean).  It appears that the lock is already active by another part of the sysem, but I've gone through the logs looking for all references to that instance of that bean (looking for it's memory address 59f5d678 - hope that's the right way to do it) - log file attached (instance-59f5d678.log).

       

      I cannot find any other threads accessing that instance - so can't undsterdant why lock aquisition would be timing out.  I've also gone through and grepped out all the activity by that thread (log file thread-http-0.0.0.0-8080-4.zip attached) and cannot see any attempt by that thread to re-enter that SFSB instance.

       

      So my questions are:

      1. Does anyone have an idea as to why I'd be getting lock timeouts?
      2. How can I tell what has the the lock when the other threads is unable to get it?
      3. How can I know what version of EJB3 and AOP souce to get to try and look in with a debugger.

       

      Please let me know if there any other info I can provide that would help.

       

      Thanks,

      Brad