4.0 Consumer OutOfMemoryError bug?

[James.Strachan]

On 6/13/06, jevans12 <jevans12@...> wrote:
> Are prefetch policy and optimized ack's Autonomous?

Yes, they are independent features. Prefetch policy is the maximum
number of unacknowledged messages delivered to a client by the broker.

optimized ack is an option to delay sending individual acks but send batches.


> As I see a consumer will
> ask for 65% of the prefetch policy messages.

The broker sends the entire prefetch size of messages to a client as
fast as possible; the client doesn't ask for messages per se - other
than subscribing with a prefetch value.


>  Does the batching of ack's
> follow this? as I receive the 65th (of 100) message a batch ack will be sent
> for those 65?

I'd have to noodle around the code but yes if enabled then optimize
acks sends in batches.

Though folks have experienced some problems with optimize acks...
http://issues.apache.org/activemq/browse/AMQ-716

so it might be worth disabling them (I've added this to the 4.0 release notes).

--

James
-------
http://radio.weblogs.com/0112098/

[jsalvo]

I am seeing this problem as well ... and I have optimizedAcknowledge disabled in my jndi.properties:

java.naming.provider.url = tcp://localhost:61616?jms.optimizeAcknowledge=false

I have this happened while testing ActiveMQ 4.0.

If I have one Connection, then multiple Sessions from the same Connection, and each Session creating its own Consumer, then the problem DOES NOT happen.

If I have multiple Connections, then one Session from each Connection, and each Session creating its own Consumer, then the problem DOES happen.

The first sign of problem from the logs was being unable to create the dynamic destination:

2006-06-16 12:48:52,778 [127.0.0.1:59267] ERROR ManagedRegionBroker            - Failed to register destination queue://SampleDynamicQueue
javax.management.InstanceAlreadyExistsException: org.apache.activemq:BrokerName=localhost,Type=Queue,Destination=SampleDynamicQueue
        at com.sun.jmx.mbeanserver.RepositorySupport.addMBean(RepositorySupport.java:452)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1410)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:936)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:337)
        at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:497)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.registerDestination(ManagedRegionBroker.java:215)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.register(ManagedRegionBroker.java:143)
        at org.apache.activemq.broker.jmx.ManagedQueueRegion.createDestination(ManagedQueueRegion.java:57)
        at org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:77)
        at org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:217)
        at org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:129)
        at org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:141)
        at org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:129)
        at org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:142)
        at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:161)
        at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:293)
        at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:73)
        at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:77)
        at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:73)
        at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:86)
        at org.apache.activemq.broker.AbstractConnection.processAddConsumer(AbstractConnection.java:427)
        at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:295)
        at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
        at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114)
        at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143)
        at java.lang.Thread.run(Thread.java:595)

This exception was logged 10 times ( 10 times because there were 10 connections ?? )

Then after that, I have:
2006-06-16 12:52:28,656 [127.0.0.1:59272] INFO  Service                        - Sync error occurred: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space


The following was logged on the console but not on the log file:
Exception in thread "ActiveMQ Transport: tcp:///127.0.0.1:59273" Exception in thread "MulticastDiscovery: tcp://jsalvo-desktop:61616" java.lang.OutOfMemoryError: Java heap space
Exception in thread "MulticastDiscovery: null" java.lang.OutOfMemoryError: Java heap space

[jsalvo]

The JMS client also logged the following exception:

javax.jms.JMSException: Java heap space
        at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:45)
        at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1137)
        at org.apache.activemq.ActiveMQSession.syncSendPacket(ActiveMQSession.java:1667)
        at org.apache.activemq.ActiveMQMessageConsumer.<init>(ActiveMQMessageConsumer.java:196)
        at org.apache.activemq.ActiveMQSession.createConsumer(ActiveMQSession.java:840)
        at org.apache.activemq.ActiveMQSession.createConsumer(ActiveMQSession.java:800)
        at ActiveMQConsumerMultipleConnections.run(ActiveMQConsumerMultipleConnections.java:42)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.OutOfMemoryError: Java heap space

[jsalvo]

> The first sign of problem from the logs was being unable to create the dynamic destination:
>
> 2006-06-16 12:48:52,778 [127.0.0.1:59267] ERROR ManagedRegionBroker            - Failed to register destination queue://SampleDynamicQueue
> javax.management.InstanceAlreadyExistsException:

Well I guess this exception is really expected, since there is more than 1 connection after all ... and 1 of the 10 connections has already created the destination.

As an aside ... what -Xms and -Xmx settings do you guys have in your production environment ? I am currently just using the default, which is -Xmx512M

[Christopher G. Stach II]

jsalvo wrote:

> I am seeing this problem as well ... and I have optimizedAcknowledge disabled
> in my jndi.properties:
>
> java.naming.provider.url =
> tcp://localhost:61616?jms.optimizeAcknowledge=false
>
> I have this happened while testing ActiveMQ 4.0.
>
> If I have one Connection, then multiple Sessions from the same Connection,
> and each Session creating its own Consumer, then the problem DOES NOT
> happen.
>
> If I have multiple Connections, then one Session from each Connection, and
> each Session creating its own Consumer, then the problem DOES happen.
>
> The first sign of problem from the logs was being unable to create the
> dynamic destination:
>
> 2006-06-16 12:48:52,778 [127.0.0.1:59267] ERROR ManagedRegionBroker          
> - Failed to register destination queue://SampleDynamicQueue
> javax.management.InstanceAlreadyExistsException:
> org.apache.activemq:BrokerName=localhost,Type=Queue,Destination=SampleDynamicQueue
>         at
> com.sun.jmx.mbeanserver.RepositorySupport.addMBean(RepositorySupport.java:452)
>         at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1410)
>         at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:936)
>         at
> com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:337)
>         at
> com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:497)
>         at
> org.apache.activemq.broker.jmx.ManagedRegionBroker.registerDestination(ManagedRegionBroker.java:215)
>         at
> org.apache.activemq.broker.jmx.ManagedRegionBroker.register(ManagedRegionBroker.java:143)
>         at
> org.apache.activemq.broker.jmx.ManagedQueueRegion.createDestination(ManagedQueueRegion.java:57)
>         at
> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:77)
>         at
> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:217)
>         at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:129)
>         at
> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:141)
>         at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:129)
>         at
> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:142)
>         at
> org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:161)
>         at
> org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:293)
>         at
> org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:73)
>         at
> org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:77)
>         at
> org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:73)
>         at
> org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:86)
>         at
> org.apache.activemq.broker.AbstractConnection.processAddConsumer(AbstractConnection.java:427)
>         at
> org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:295)
>         at
> org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
>         at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
>         at
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
>         at
> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
>         at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114)
>         at
> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
>         at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
>         at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143)
>         at java.lang.Thread.run(Thread.java:595)
>
> This exception was logged 10 times ( 10 times because there were 10
> connections ?? )
>
> Then after that, I have:
> 2006-06-16 12:52:28,656 [127.0.0.1:59272] INFO  Service                      
> - Sync error occurred: java.lang.OutOfMemoryError: Java heap space
> java.lang.OutOfMemoryError: Java heap space
>
>
> The following was logged on the console but not on the log file:
> Exception in thread "ActiveMQ Transport: tcp:///127.0.0.1:59273" Exception
> in thread "MulticastDiscovery: tcp://jsalvo-desktop:61616"
> java.lang.OutOfMemoryError: Java heap space
> Exception in thread "MulticastDiscovery: null" java.lang.OutOfMemoryError:
> Java heap space
>
>
>
> --
> View this message in context: http://www.nabble.com/4.0-Consumer-OutOfMemoryError-bug--t1707655.html#a4894234
> Sent from the ActiveMQ - User forum at Nabble.com.
>

We're getting very similar memory consumption until permgen space fills
up and MBean registration exceptions, but only in the broker which runs
in its own JVM.  We don't use discovery, though.  We also have
optimizeAcknowledge turned off.  Somehow, we run out of 512MB with fewer
than ten thousand very small messages (just a couple of Integers.)

--
Christopher G. Stach II

[jsalvo]

After restarting the broker and starting the test client, I was not able to reproduce the problem until after some significant amount of time.

I believe that the reason is not because of the number of connections ... The problem is also not related to consumers ( even with consumers not cleanup cleanly ).

Instead, the problem seems to be with producers.

After running a JMS client producer with produced lots of messages ( non-transacted, auto-acknowledged ), JConsole shows the memory heap usage DOES NOT go down, even after telling JConsole to do a garbage collection.

However, after running a JMS client consumer, JConsole shows the memory heap usage DOES go down after telling JConsole to do a garbage collection ... even if the JMS client producer did not clean up properly (e.g. testing how resilient the JMS provider is when a JMS client JVM is killed, etc.. )

I ran this test a couple of times, and the evidence so far shows that the broker is somehow not releasing some resource that the JMS client producer had even after the JMS client has exited / disconnected.

Apart from that, even when there are no JMS clients, the memory usage goes up continuously ... but on slightly. Then again, even after I tell JConsole to do a GC, the heap memory usage graph does not go down as well ... So that maybe another case separate from the producer case.

[James.Strachan]

If you can figure out how to reproduce the JMX exception in a JUnit
test case we can fix it.

With regards memory consumption; you are saying RAM usage grows as you
produce messages. This makes sense since we tend to cache messages
around so that they are in RAM when consumers start consuming them.
For non-pesistent messaging all messages stay in RAM. So firstly are
you using persistent messaging? (i.e. what is the delivery mode on the
producer).

Secondly the journal caches messages and acks around in RAM until a
checkpoint to JDBC occurs (for persistent messaging) - so you should
see RAM use go down after you've sent a bunch of persistent messags,
then some time later the checkpoint happens.

On 6/16/06, jsalvo <jesus.salvo@...> wrote:

>
> After restarting the broker and starting the test client, I was not able to
> reproduce the problem until after some significant amount of time.
>
> I believe that the reason is not because of the number of connections ...
> The problem is also not related to consumers ( even with consumers not
> cleanup cleanly ).
>
> Instead, the problem seems to be with producers.
>
> After running a JMS client producer with produced lots of messages (
> non-transacted, auto-acknowledged ), JConsole shows the memory heap usage
> DOES NOT go down, even after telling JConsole to do a garbage collection.
>
> However, after running a JMS client consumer, JConsole shows the memory heap
> usage DOES go down after telling JConsole to do a garbage collection ...
> even if the JMS client producer did not clean up properly (e.g. testing how
> resilient the JMS provider is when a JMS client JVM is killed, etc.. )
>
> I ran this test a couple of times, and the evidence so far shows that the
> broker is somehow not releasing some resource that the JMS client producer
> had even after the JMS client has exited / disconnected.
>
> Apart from that, even when there are no JMS clients, the memory usage goes
> up continuously ... but on slightly. Then again, even after I tell JConsole
> to do a GC, the heap memory usage graph does not go down as well ... So that
> maybe another case separate from the producer case.
>
>
>
>
> --
> View this message in context: http://www.nabble.com/4.0-Consumer-OutOfMemoryError-bug--t1707655.html#a4895366
> Sent from the ActiveMQ - User forum at Nabble.com.
>
>

--

James
-------
http://radio.weblogs.com/0112098/

[jsalvo]

> With regards memory consumption; you are saying RAM usage grows as you
> produce messages. This makes sense since we tend to cache messages
> around so that they are in RAM when consumers start consuming them.
> For non-pesistent messaging all messages stay in RAM. So firstly are
> you using persistent messaging? (i.e. what is the delivery mode on the
> producer).

I was using PERSISTENT mode:

      Connection conn = this.factory.createConnection();
      Session session = conn.createSession( false, Session.AUTO_ACKNOWLEDGE );
      MessageProducer qProducer = session.createProducer( this.myQueue);    
      qProducer.setDeliveryMode(DeliveryMode.PERSISTENT);

> Secondly the journal caches messages and acks around in RAM until a
> checkpoint to JDBC occurs (for persistent messaging) - so you should
> see RAM use go down after you've sent a bunch of persistent messags,
> then some time later the checkpoint happens.

This does not seem to be the case for me. Having said that, when I was running all of these test, I was actually using kaha persistence:

    <persistenceAdapter>
      <kahaPersistentAdaptor dir = "activemq-data"/>
    </persistenceAdapter>

I'll try to see if it happens as well with the original config:

    <persistenceAdapter>
      <journaledJDBC journalLogFiles="5" dataDirectory="../activemq-data"/>
    </persistenceAdapter>