2 Replies Latest reply on Apr 29, 2016 5:27 PM by brasmussen

    Troubleshooting pooled-connection-factory and blocking timeouts

    brasmussen

      We have been trying to do away with having a connection factory for every queue (we have 8 queues right now) in favor of a global pooled connection factory with Artemis. The server is able to process data for about 1 - 2 hours (depending on how heavy of a load we throw at the server) before it starts to throw the below stack trace. I would think that the blocking timeout would make sense if, after a while, the error was thrown less as resources freed up, and then processing returned to normal. The connections are not freed up, though. The only thing I can think of is a possible resource leak, but my first inspection did not lead to anything.

       

      The below configurations are mainly baselines. In other words, I don't know if giving Artemis 100 threads is enough? Too much? Any input on this error is welcome.

       

       

      Some relevant configurtaions:

      standalone.conf:

      JAVA_OPTS="$JAVA_OPTS -Dactivemq.artemis.client.global.thread.pool.max.size=100"

       

       

      standalone-full.xml:

      <server name="default" thread-pool-max-size="100" scheduled-thread-pool-max-size="10">

          ...

          <pooled-connection-factory name="activemq-ra" transaction="xa" entries="java:/JmsXA java:jboss/DefaultJMSConnectionFactory" connectors="in-vm" max-pool-size="100" />

          ...

      </server>

       

       

      The stack trace itself:

      javax.jms.JMSException: Could not create a session: IJ000453: Unable to get managed connection for java:/JmsXA

              at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.allocateConnection(ActiveMQRASessionFactoryImpl.java:895) ~[?:?]

              at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.createSession(ActiveMQRASessionFactoryImpl.java:520) ~[?:?]

              at <My factory-accessing class, Session session = conn.createSession(false, Session.AUTO_ACKNOWLEDGE);> ~[MyJar.jar:5.0.0]

              at <My factory-accessing class, method call to above line> ~[MyJar.jar:5.0.0]

              at sun.reflect.GeneratedMethodAccessor114.invoke(Unknown Source) ~[?:?]

              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_66]

              at java.lang.reflect.Method.invoke(Method.java:497) ~[?:1.8.0_66]

              at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:49) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47) ~[wildfly-jpa-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) ~[wildfly-ee-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:275) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:327) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:239) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:66) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[jboss-invocation-1.4.1.Final.jar!/:1.4.1.Final]

              at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) ~[wildfly-ejb3-10.0.0.Final.jar!/:10.0.0.Final]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[?:?]

              at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:64) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[?:?]

              at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) ~[?:?]

              at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:636) ~[?:?]

              at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:61) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[?:?]

              at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:356) ~[?:?]

              at org.jboss.invocation.PrivilegedWithCombinerInterceptor.processInvocation(PrivilegedWithCombinerInterceptor.java:80) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[?:?]

              at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) ~[?:?]

              at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:195) ~[?:?]

              at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) ~[?:?]

              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) ~[?:?]

              at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) ~[?:?]

              at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73) ~[?:?]

              at <My factory-accessing class> ~[MyJar:5.0.0]

              at <A calling class> ~[MyJar:5.0.0]

              at <A calling class> ~[MyJar:5.0.0]

              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_66]

              at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_66]

              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_66]

              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_66]

              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_66]

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_66]

        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_66]

      Caused by: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/JmsXA

              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:656) ~[?:?]

              at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429) ~[?:?]

              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747) ~[?:?]

              at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.allocateConnection(ActiveMQRASessionFactoryImpl.java:853) ~[?:?]

              ... 64 more

      Caused by: javax.resource.ResourceException: IJ000655: No managed connections available within configured blocking timeout (30000 [ms])

              at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool.getConnection(SemaphoreConcurrentLinkedDequeManagedConnectionPool.java:564) ~[?:?]

              at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:708) ~[?:?]

              at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:607) ~[?:?]

              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:590) ~[?:?]

              at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:429) ~[?:?]

              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:747) ~[?:?]

              at org.apache.activemq.artemis.ra.ActiveMQRASessionFactoryImpl.allocateConnection(ActiveMQRASessionFactoryImpl.java:853) ~[?:?]

              ... 64 more

        • 1. Re: Troubleshooting pooled-connection-factory and blocking timeouts
          jbertram

          There is certainly no strict need to have a connection factory for each queue.

           

          It's worth noting that the message "IJ000453: Unable to get managed connection for java:/JmsXA" isn't directly related to thread pool utilization.  That message simply means your connection pool is exhausted.  My recommendation:

           

          • Put logging statements around when you create/close connections from JmsXA and examine the log to see if you have matching numbers of both.
          • Take periodic thread dumps so you can see what your application is doing.  I've often seen this problem occur when the application gets a connection from the pool and then invokes another misbehaving service (e.g. long database query) which delays the application from returning the connection to the pool and thus starves it.
          • 2. Re: Troubleshooting pooled-connection-factory and blocking timeouts
            brasmussen

            As you Justin suggested, this was not an issue caused by thread pool utilization. We were leaking resources by not closing all the Sessions / Producers we were creating off our connection factory. After reviewing our code a second time and closing those resources in a finally block, the application has run for a few hours. Letting our system run for the weekend for real verification.

             

            Thanks!