LocalTx, ClientTransaction leak?

[ydzsidemiik]

Hi,

I am using JBoss Messaging 1.4.0.GA on JBoss AS 4.2.1.GA. While I am still confused as to what exactly is going on, I do notice that an awful lot of memory -- running into the hundreds of megabytes after a couple of weeks of uptime -- is being spent on instances of these classes.

Here is a sample from a memory profiler:

Name NumberOfObjects ShallowSize Objects(+/-) Size(+/-)
char[] "3,279,908" "207,726,784" "1,469,889" "113,996,504"
java.lang.String "3,208,298" "76,999,152" "1,325,817" "31,819,608"
org.jboss.jms.tx.LocalTx "884,110" "14,145,760" "713,639" "11,418,224"
org.jboss.jms.tx.ClientTransaction "884,102" "21,218,448" "713,571" "17,125,704"
EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap$Entry "886,174" "21,268,176" "705,474" "16,931,376"
java.util.HashMap$Entry "1,775,551" "42,613,224" "522,401" "12,537,624"
org.jboss.messaging.core.impl.message.SimpleMessageReference "268,469" "10,738,760" "91,079" "3,643,160"
org.jboss.jms.message.JBossMapMessage "288,431" "20,767,032" "90,991" "6,551,352"
byte[] "365,068" "70,405,112" "88,651" "18,667,008"
java.util.LinkedList$Entry "287,433" "6,898,392" "87,552" "2,101,248"
java.util.concurrent.ConcurrentLinkedQueue$Node "162,932" "2,606,912" "80,845" "1,293,520"
java.util.HashMap$EntrySet "249,611" "3,993,776" "80,719" "1,291,504"
java.lang.Long "327,054" "5,232,864" "55,218" "883,488"
java.lang.StringBuilder "52,649" "842,384" "41,528" "664,448"

Does it make sense to have almost a million of these objects hanging around after a few days uptime? Am I doing something wrong?

[ydzsidemiik]

I've studied the GC root paths for some of these objects, they all look like this:

org.jboss.jms.tx.ClientTransaction
<- value of EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap$Entry
<- [287] of EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap$Entry[1025]
<- table of EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap
<- transactions of org.jboss.jms.tx.ResourceManager
<- resourceManager of org.jboss.jms.client.state.ConnectionState
<- parent of org.jboss.jms.client.state.SessionState
<- parent of org.jboss.jms.client.state.ConsumerState
<- state of org.jboss.jms.client.delegate.ClientConsumerDelegate [Stack Local]

Where the stack local is reported to be on the stack of 'Connection Consumer for dest JBossQueue[...]', which is a thread feeding an MDB.

I've collected allocation traces for some of these objects as well, and they all look like this:

org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(Xid, int)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.delistResource(XAResource, int)
org.jboss.resource.adapter.jms.JmsSession.close()
... earlier frames vary ...

It's strange that the traces cut off there since (looking at the source), no allocations occur in that function. However, I tried to figure out where the trace went from there and my guess is something like MessagingXAResource.end -> MessagingXAResource.unsetCurrentTransactionId -> ResourceManager.createLocalTx, which seems to be a plausible source of these allocations.

I don't know where to go from here. Please help :(

[timfox]

Does this occur with the latest version of JBM? (1.4.0.SP3)

[ydzsidemiik]

I haven't tried upgrading, the schema changes since 1.4.0.GA pose a significant logistical challenge for me.

I will set up a test environment to find out.

[ydzsidemiik]

Ok, I have just set up JBAS 4.2.2.GA with JBM 1.4.0.SP3 (it would be nice to have a pre-packaged JBAS+JBM distribution), and have found that the issue persists in pretty much the exact same way.

Can I provide any additional telemetry?

[timfox]

.. earlier frames vary ...

Can you post your full allocation traces?

[timfox]

Also if you give some kind of description of what your app does, does it use other products (e.g. Spring), that would be good.

You seem to be opening and closing a lot of sessions.

[ydzsidemiik]

Our application is store-and-forward middleware for a telecom messaging protocol. We use JBAS and JBM built off the 'all' JBAS configuration, with Apache MINA, SLF4J, Commons Lang, and the Postgres driver being included in the JBAS configuration's lib directory. We do not use Spring, nor any other third party libraries or frameworks besides these.

The application is composed of two parts; a JCA resource adapter which acts as a protocol driver for this messaging protocol and an EJB3 component which contains the routing logic. The EJB3 component contains both custom MDBs, driven by our resource adapter, and JMS MDBs. The custom MDBs act as listeners and enqueue messages that they receive into JBM queues; the JMS MDBs act as senders, listening to those queues and calling upon the resource adapter again to transmit messages to various external endpoints.

It is true that we open a lot of sessions; because the protocol is not transacted, each message is logically independent of any others. As a result, we enqueue each message using a closure (which you can see listed below) which obtains a connection and a session, then carefully releases both.

Here are some of the traces that seem typical. Again, I do not know why they appear to be cut off. It may be a misunderstanding on my part or a quirk of my profiler.

This one seems to be an invocation of one of the custom MDBs by the RA.

org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(Xid, int)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.delistResource(XAResource, int)
org.jboss.resource.adapter.jms.JmsSession.close()
com.acme.gateway.util.jms.JmsOperation.execute()
com.acme.gateway.EnqueuerImpl.enqueue(EnqueuerImpl$QueueName, RoutableRequest, RoutableRequest, int, EnqueuerImpl$Header[])
com.acme.gateway.EnqueuerImpl.enqueueOutboundLive(RoutableRequest, Bind)
$Proxy164.enqueueOutboundLive(RoutableRequest, Bind)
com.acme.gateway.ClientGateway.onRoutable(RoutableRequest)
com.acme.gateway.smppra.adapter.PDUListenerCoalescingAdapter.onSubmit(SubmitSM)
java.lang.reflect.Method.invoke(Object, Object[])
com.acme.gateway.smppra.spi.ClientManagedConnection.dispatch(PDU, MessageEndpoint)
com.acme.gateway.smppra.spi.BaseManagedConnection.messageReceived(Object)
org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run()
com.acme.gateway.smppra.spi.SmppResourceAdapter$3$1.run()
org.jboss.util.threadpool.BasicTaskWrapper.run()
EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run()
java.lang.Thread.run()

Don't know what this one is.

org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(Xid, int)
com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare()
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(boolean, AbstractRecord)
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(boolean)
com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(boolean)
com.arjuna.ats.arjuna.coordinator.BasicAction.End(boolean)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(boolean)
com.arjuna.ats.arjuna.AtomicAction.commit(boolean)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate()
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit()
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit()
org.jboss.util.threadpool.BasicTaskWrapper.run()
EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run()
java.lang.Thread.run()

Another invocation of one of the custom MDBs by the RA.

org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(Xid, int)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.delistResource(XAResource, int)
org.jboss.resource.adapter.jms.JmsSession.close()
com.acme.gateway.util.jms.JmsOperation.execute()
com.acme.gateway.EnqueuerImpl.enqueue(EnqueuerImpl$QueueName, RoutableRequest, RoutableRequest, int, EnqueuerImpl$Header[])
com.acme.gateway.EnqueuerImpl.enqueueInboundLive(RoutableRequest, String)
$Proxy164.enqueueInboundLive(RoutableRequest, String)
com.acme.gateway.CarrierGateway.onRoutable(RoutableRequest)
com.acme.gateway.smppra.adapter.PDUListenerCoalescingAdapter.onDeliver(DeliverSM)
java.lang.reflect.Method.invoke(Object, Object[])
com.acme.gateway.smppra.spi.CarrierManagedConnection.dispatch(PDU, MessageEndpoint)
com.acme.gateway.smppra.spi.BaseManagedConnection.messageReceived(Object)
org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run()
com.acme.gateway.smppra.spi.SmppResourceAdapter$3$1.run()
org.jboss.util.threadpool.BasicTaskWrapper.run()
EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run()
java.lang.Thread.run()

This one is an invocation of a JMS MDB by the container.

org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.end(Xid, int)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.delistResource(XAResource, int)
org.jboss.resource.adapter.jms.JmsSession.close()
com.acme.gateway.util.jms.JmsOperation.execute()
com.acme.gateway.EnqueuerImpl.enqueue(EnqueuerImpl$QueueName, RoutableRequest, RoutableRequest, int, EnqueuerImpl$Header[])
com.acme.gateway.EnqueuerImpl.enqueueInboundSent(Message, RoutableRequest, RoutableRequest, Provider, Bind, Aggregation)
$Proxy164.enqueueInboundSent(Message, RoutableRequest, RoutableRequest, Provider, Bind, Aggregation)
com.acme.gateway.ClientSender.complete()
com.acme.gateway.ClientSender.onRoutable(RoutableRequest)
com.acme.gateway.smppra.adapter.PDUListenerCoalescingAdapter.onDeliver(DeliverSM)
com.logica.smpp.pdu.DeliverSM.accept(PDUListener)
com.logica.smpp.pdu.DeliverSM.accept(PDUListener)
com.acme.gateway.Sender.onMessage(Message)
org.jboss.util.threadpool.BasicTaskWrapper.run()
EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run()
java.lang.Thread.run()

Here is the listing of the closure I wrote to help me manage JMS resources, which appears in the traces:

package com.acme.gateway.util.jms;

import javax.ejb.EJBException;
import javax.jms.Connection;
import javax.jms.ConnectionFactory;
import javax.jms.JMSException;
import javax.jms.Session;

public abstract class JmsOperation
{
 private static final org.apache.log4j.Logger log =
 org.apache.log4j.Logger.getLogger(JmsOperation.class);

 private final ConnectionFactory connectionFactory;
 private Connection connection;
 private Session session;

 public JmsOperation(ConnectionFactory connectionFactory)
 {
 this.connectionFactory = connectionFactory;
 }

 protected ConnectionFactory getConnectionFactory()
 {
 return connectionFactory;
 }

 protected Connection getConnection()
 {
 return connection;
 }

 protected Session getSession()
 {
 return session;
 }

 protected abstract void executeInternal() throws JMSException;

 public void execute()
 {
 try
 {
 connection = connectionFactory.createConnection();

 if (log.isTraceEnabled())
 {
 log.trace("execute: Got connection " + connection);
 }

 session = connection.createSession(true, Session.SESSION_TRANSACTED);

 if (log.isTraceEnabled())
 {
 log.trace("execute: Got session " + session);
 }

 executeInternal();
 }
 catch (JMSException e)
 {
 throw new EJBException(e);
 }
 finally
 {
 try
 {
 if (session != null)
 {
 session.close();
 }
 }
 catch (JMSException e)
 {
 log.warn("execute: Failed to close the session", e);
 }
 finally
 {
 session = null;

 try
 {
 if (connection != null)
 {
 connection.close();
 }
 }
 catch (JMSException e)
 {
 log.warn("execute: Failed to close the connection", e);
 }
 finally
 {
 connection = null;
 }
 }
 }
 }
}

You would subclass it and implement your JMS code inside executeInternal(), making use of the Connection and Session that would be available during the execution of that function.

Sincere thanks for your time :)

[timfox]

This doesn't look right to me.

The only time that creating a connection, creating a session, doing something, then closing them is not an antipattern, is when you are using a JMS JCA resource adaptor.

This is because when using a resource adaptor, when you call createConnection() it doesn't actually create an actual new JMS connection, it just retrieves one from a pool that the resource adaptor maintains.

If you're not using a JCA resource adaptor then each call to createConnection, createSession etc will actually create new JMS connections, sessions etc.

Connections and Sessions are heavyweight objects and designed to be re-used. If this is the case then performance is going to very, very bad. Hence it's an antipattern.

If you're seeing lots of actual sessions created it would imply you're not actually using the JCA resource adaptor.

Can you confirm that the connections you create are created using the JCA JMS managed connection factory?

(This is the connection factory you get by looking up typically from java:/JmsXA)

http://wiki.jboss.org/wiki/Wiki.jsp?page=JBossJMSRA

[timfox]

Another observation.

In your helper class there's no need to explicitly close the session in your finally block.

Closing the connection will automatically ensure the session is closed (or returned to the pool).

finally
 {

 try
 {
 if (connection != null)
 {
 connection.close();
 }
 }
 catch (JMSException e)
 {
 log.warn("execute: Failed to close the connection", e);
 }

 }

Is fine.

Looking at your trace, I can see all the allocations are from JBoss JMS Resource adaptor code, not JBoss Messaging code (the resource adaptor is part of JBoss AS, not JBM), and specifically from session.close().

I would try not closing the session explicitly and see what happens.

[timfox]

It would be good if you could provide full allocation traces.

I don't know what profiler you are using, but I believe that JProfiler by default only shows a certain depth, this is configurable.

[ydzsidemiik]

I am using the JMS RA. I look up the JMS connection factory using java:/JmsXA, my performance is reasonable, and I can see in the JMX console that the pool has connections in it and that they are being used. From the beginning I based this design on the assumption that the JMS connections would be pooled. Otherwise, as you note, it wouldn't work very well at all.

I propose that the JMS resource adapter could not be allocating or holding references to JBM internal objects. The trace only goes as far as to identify JcaXAResourceWrapper.end as being on the path to where the actual allocations occur, although it cuts off there for reasons unknown to me but probably having to do with my profiler.

I propose that the allocation could not actually occur in JcaXAResourceWrapper.end because that method contains no allocations of any kind. In my initial investigation of the JBM source, I guessed that the following frames which we do not see may be MessagingXAResource.end -> MessagingXAResource.unsetCurrentTransactionId -> ResourceManager.createLocalTx, a plausible control flow to a function where the objects observed to be leaking are actually being allocated. However, I cannot say with certainty that this is the case.

As per your suggestion, I will try not closing my JMS sessions explicitly.

[ydzsidemiik]

"timfox" wrote:
It would be good if you could provide full allocation traces.

I don't know what profiler you are using, but I believe that JProfiler by default only shows a certain depth, this is configurable.

I am using YourKit, but I will investigate this also.

[timfox]

Personally I try and discourage people from relying on resource adaptor caching and using the "ejb-style" create connection, create session, do something, close connection approach, since I believe this encourages poor JMS habits.

One thing to note is the JMS resource adapter only caches JMS connection/sessions. It does not cache JMS producers or consumers.

This means it will still create a new producer on each action. This isn't too bad since the producer is a fairly lightweight object living on the client side only. However if you are creating consumers then this will require a server call to create one on the server for each action, significantly reducing performance.

[timfox]

Not related to you case, but creating consumers for each action is exactly what the Spring JMS template does, and is one reason why we can't recommend it.