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

    Troubleshooting pooled-connection-factory and blocking timeouts

    Benedict Rasmussen Newbie

      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
          Justin Bertram Master

          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
            Benedict Rasmussen Newbie

            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!