5 Replies Latest reply on Aug 2, 2016 6:09 AM by mayerw01

    wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS

    mayerw01

      It looks like this bug had been come in to WildFly again [WFLY-5568] Concurrent access timeout -- could not obtain lock within 5000 MILLISECONDS - JBoss Issue Tracker

       

      2016-07-31 12:45:05,029 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 1) WFLYEJB0034: EJB Invocation failed on component BeanStatisticsBean for method public abstract void de.ejb3buch.ticket2rock.session.statistics.BeanStatisticsLocal.reportNewObject(java.lang.Object): javax.ejb.ConcurrentAccessTimeoutException: WFLYEJB0241: EJB 3.1 PFD2 4.8.5.5.1 concurrent access timeout on BeanStatisticsBean - could not obtain lock within 5000MILLISECONDS

          at org.jboss.as.ejb3.concurrency.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:106)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)

          at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)

          at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)

          at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)

          at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)

      ....

      at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340)

          at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)

          at org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:161)

          ... 43 more

       

      Then WildFly is stuck

        • 1. Re: wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS
          mayerw01

          For add'l information. The BeanStatisticsBean is a Singleton bean which deployed without any issues in wildfly-10.0.0.Final

           

          @Singleton

          @ExcludeDefaultInterceptors

          public class BeanStatisticsBean implements BeanStatisticsLocal,

                  BeanStatistics {

              Map<Class, Integer> classUsage = new HashMap<Class, Integer>();

              Map<Method, Integer> methodUsage = new HashMap<Method, Integer>();

              Map<Method, Long> methodDuration = new HashMap<Method, Long>();

           

              @SuppressWarnings("rawtypes")

              public Map<Class, Integer> getClassUsage() {

                  return classUsage;

              }

           

              public Map<Method, Integer> getMethodUsage() {

                  return methodUsage;

              }

           

              public Map<Method, Long> getMethodTotalDuration() {

                  return methodDuration;

              }

           

              public void reportNewObject(Object object) {

                  if (!classUsage.containsKey(object.getClass())) {

                      // First object of the given class

                      classUsage.put(object.getClass(), 1);

                  } else {

                      // Other objects of this class already exist

                      Integer currentCount = classUsage.get(object

                              .getClass());

                      currentCount++;

                      classUsage

                              .put(object.getClass(), currentCount);

                  }

              }

           

              public void reportMethodCall(Method method) {

                  if (!methodUsage.containsKey(method)) {

                      // First object of the given class

                      methodUsage.put(method, 1);

                  } else {

                      // Other objects of this class already exist

                      Integer currentCount = methodUsage.get(method);

                      currentCount++;

                      methodUsage.put(method, currentCount);

                      methodUsage.put(method, currentCount++);

                  }

              }

           

              public void reportMethodDuration(Method method, long duration) {

                  if (!methodDuration.containsKey(method)) {

                      // First object of the given class

                      methodDuration.put(method, duration);

                  } else {

                      // Other objects of this class already exist

                      Long totalDuration = methodDuration

                              .get(method);

                      totalDuration += duration;

                      methodDuration.put(method, totalDuration);

                  }

              }

          }

          • 2. Re: wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS
            ctomc

            Problem doesn't look related to deployment but to runtime.

             

            Stack trace wise this looks different problem to what is in linked jira.

            What happens is that you have bunch of threads (ejbs) all accessing one singleton bean and calling reportNewObject method on it.

             

            So there is lots of concurrency going on and some calls start timeouting as they cannot access that method in defined (well in this case default) timeout for concurrent access.

             

            I would change you BeanStaticits impl to be Stateless bean with all maps being static and of ConcurrentHashMap instance.

            than also properly apply concurrent operations on the maps (putIfAbsent vs put, etc)

            Or even go bit further and implement all this via ReadWriteLock.

             

            Doing this will make your problem go away, and also speed up execution time considerably.

            • 3. Re: wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS
              mayerw01

              Changing the BeanStatisticsBean to Stateless is not an option since this Bean keeps track of some statistical values(like the users currently logged in). I understand these figures would have gone when using Stateless.

              My understanding is also that the main reason for adding Singleton to the Spec is making it easier to manage concurrency.

              Anyway as mentioned before this Bean deploys without any issue in wildfly-10.0.0.Final. So I hesitate that this is caused by an programming error.

              And even when you are right then the WildFly might fire some exceptions but it should not hang up.

              • 4. Re: wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS
                ctomc

                Wolfgang Mayer wrote:

                 

                Changing the BeanStatisticsBean to Stateless is not an option since this Bean keeps track of some statistical values(like the users currently logged in).

                That is why I suggest doing that when also changing maps to be static, so they would be shared between all instances of stateless bean. (yes that is technically making stateless bean somewhat have shared state)

                 

                Wolfgang Mayer wrote:

                Anyway as mentioned before this Bean deploys without any issue in wildfly-10.0.0.Final. So I hesitate that this is caused by an programming error.

                And even when you are right then the WildFly might fire some exceptions but it should not hang up.

                Yes it deployed fine on 10.0 and it deploys fine on 10.1.

                at runtime you get different behavior, but just slight change in concurrency levels also on 10.0 would cause the same issue. You (w)are somewhat lucky.

                 

                But in any case, doing what you are doing would be better suited for interceptor, at least the performance storing part, the reading would than be done by singleton bean or something like that.

                 

                Also what happens if you mark your singleton with @TransactionAttribute(value = TransactionAttributeType.NEVER)

                this way it wouldn't participate in the transaction of calling ejb bar.

                • 5. Re: wildfly-10.1.0.CR1: could not obtain lock within 5000MILLISECONDS
                  mayerw01

                  Actually the call to BeanStatisticsBean is done via an @Interceptor and setting @TransactionAttribute(value = TransactionAttributeType.NEVER) does also not help

                   

                  @InterceptorBinding

                  @Inherited

                  @Target( { TYPE })

                  @Retention(RUNTIME)

                  public @interface BeanStatistics {}

                   

                  ------

                   

                  public @BeanStatistics

                  @Interceptor

                  class BeanStatisticsInterceptor {

                      private BeanStatisticsLocal beanstats;

                      @EJB(beanName = "BeanStatisticsBean")

                      public void setBeanStatisticsBean(BeanStatisticsLocal c) {

                          beanstats = c;

                      }

                   

                      @PostConstruct

                      public void onPostConstruct(InvocationContext ctx)  {

                          beanstats.reportNewObject(ctx.getTarget());

                              try {

                                  ctx.proceed();

                              } catch (Exception ex) {

                                  Logger.getLogger(BeanStatisticsInterceptor.class.getName()).log(Level.SEVERE, null, ex);

                              }

                      }

                   

                      @AroundInvoke

                      public Object onMethodCall(InvocationContext ctx) throws Exception {

                          beanstats.reportMethodCall(ctx.getMethod());

                          long startTime = System.currentTimeMillis();

                          try {

                              return ctx.proceed();

                          }

                              finally {

                              long duration = System.currentTimeMillis() - startTime;

                              beanstats.reportMethodDuration(ctx.getMethod(), duration);

                          }

                      }

                  }