ActiveMQ embedded broker 100% cpu usage

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
9 messages Options
Reply | Threaded
Open this post in threaded view
|

ActiveMQ embedded broker 100% cpu usage

nyariz
Hi,

We have an ActiveMQ multibroker network with 4 nodes. There is 1 master
node and 3 slave nodes,
every message is broadcasted between all nodes using persistent topics and
durable subscriptions.
ActiveMQ (version 5.9.1) is embedded into a Spring based Java Web
Application running on Tomcat 7.
It works well mostly, but today we had to face a serious issue for the
second time.

The connection between the master node and a slave node is lost:

WARN   2015.01.10 14:00:29,281
org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
exception processing local command
java.net.SocketException: Connection reset
        at
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
        at
org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
        at java.io.DataOutputStream.flush(DataOutputStream.java:123)
        at
org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:176)
        at
org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
        at
org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
        at
org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
        at
org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
        at
org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
        at
org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
        at
org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
        at
org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
        at
org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at
org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
        at
org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:29,335
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
INFO   2015.01.10 14:00:29,346
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.net.SocketException: Connection reset
INFO   2015.01.10 14:00:29,346
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
INFO   2015.01.10 14:00:29,346
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
INFO   2015.01.10 14:00:29,346
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
INFO   2015.01.10 14:00:29,347
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
WARN   2015.01.10 14:00:29,346
org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
exception processing local command
java.io.EOFException
        at java.io.DataInputStream.readFully(DataInputStream.java:197)
        at java.io.DataInputStream.readFully(DataInputStream.java:169)
        at
org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightUnmarshalByteSequence(BaseDataStreamMarshaller.java:440)
        at
org.apache.activemq.openwire.v10.MessageMarshaller.tightUnmarshal(MessageMarshaller.java:72)
        at
org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightUnmarshal(ActiveMQMessageMarshaller.java:66)
        at
org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightUnmarshal(ActiveMQTextMessageMarshaller.java:66)
        at
org.apache.activemq.openwire.OpenWireFormat.doUnmarshal(OpenWireFormat.java:371)
        at
org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:285)
        at
org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221)
        at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213)
        at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:29,347
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819@62000
shutdown due to a local error: java.io.EOFException
INFO   2015.01.10 14:00:29,383
org.apache.activemq.network.DemandForwardingBridgeSupport -
PERCMASTERBroker bridge to BALASSIBroker stopped


After a few seconds the connection has been reestablished automatically:

INFO   2015.01.10 14:00:45,563
org.apache.activemq.broker.TransportConnection - Started responder end of
duplex bridge clientConnector@ID:balaserver1-45698-1418680167169-1:1
INFO   2015.01.10 14:00:45,570
org.apache.activemq.network.DemandForwardingBridgeSupport - Network
connection between vm://PERCMASTERBroker#42 and tcp:///10.10.0.58:54625@62000
(BALASSIBroker) has been established.

But after then the cpu usage goes up to 100% (effectively killed the
application) and the log full of duplicate message errors:

WARN   2015.01.10 14:00:46,599
org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a:Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
- cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36636, 4
WARN   2015.01.10 14:00:46,639 org.apache.activemq.broker.region.Queue -
duplicate message from store
ID:balaserver1-45698-1418680167169-6:1:2:1:36636, redirecting for dlq
processing
WARN   2015.01.10 14:00:48,526
org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a:Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
- cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36637, 4
WARN   2015.01.10 14:00:48,528 org.apache.activemq.broker.region.Queue -
duplicate message from store
ID:balaserver1-45698-1418680167169-6:1:2:1:36637, redirecting for dlq
processing
WARN   2015.01.10 14:00:48,546
org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a:Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:3,hasSpace:true
- cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:3:1:37026, 4
WARN   2015.01.10 14:00:48,547 org.apache.activemq.broker.region.Queue -
duplicate message from store
ID:balaserver1-45698-1418680167169-6:1:3:1:37026, redirecting for dlq
processing
WARN   2015.01.10 14:00:48,560
org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a:Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
- cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36638, 4

The only thing we could do is stop the application (on all nodes), clear
the activemq-data folder and restart the application.
When we simply tried to restart it, the startup process has stucked with no
error message, just using 100% of the CPU.

Do you have any idea what could have happened here?

Thanks,

Zoltan Nyari
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Kevin Burton
$100 says it’s spending all its time doing full GC. Look at your GC log..
I bet it will keep printing “Full GC” constantly.

Kevin

On Sat, Jan 10, 2015 at 7:19 AM, Zoltán Nyári <[hidden email]>
wrote:

> Hi,
>
> We have an ActiveMQ multibroker network with 4 nodes. There is 1 master
> node and 3 slave nodes,
> every message is broadcasted between all nodes using persistent topics and
> durable subscriptions.
> ActiveMQ (version 5.9.1) is embedded into a Spring based Java Web
> Application running on Tomcat 7.
> It works well mostly, but today we had to face a serious issue for the
> second time.
>
> The connection between the master node and a slave node is lost:
>
> WARN   2015.01.10 14:00:29,281
> org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> exception processing local command
> java.net.SocketException: Connection reset
>         at
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
>         at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
>         at
>
> org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
>         at java.io.DataOutputStream.flush(DataOutputStream.java:123)
>         at
>
> org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:176)
>         at
>
> org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
>         at
>
> org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
>         at
>
> org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
>         at
>
> org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
>         at
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
>         at
>
> org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
>         at
>
> org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:29,335
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> INFO   2015.01.10 14:00:29,346
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.net.SocketException: Connection reset
> INFO   2015.01.10 14:00:29,346
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> INFO   2015.01.10 14:00:29,346
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> INFO   2015.01.10 14:00:29,346
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> INFO   2015.01.10 14:00:29,347
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> WARN   2015.01.10 14:00:29,346
> org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> exception processing local command
> java.io.EOFException
>         at java.io.DataInputStream.readFully(DataInputStream.java:197)
>         at java.io.DataInputStream.readFully(DataInputStream.java:169)
>         at
>
> org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightUnmarshalByteSequence(BaseDataStreamMarshaller.java:440)
>         at
>
> org.apache.activemq.openwire.v10.MessageMarshaller.tightUnmarshal(MessageMarshaller.java:72)
>         at
>
> org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightUnmarshal(ActiveMQMessageMarshaller.java:66)
>         at
>
> org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightUnmarshal(ActiveMQTextMessageMarshaller.java:66)
>         at
>
> org.apache.activemq.openwire.OpenWireFormat.doUnmarshal(OpenWireFormat.java:371)
>         at
>
> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:285)
>         at
>
> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221)
>         at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213)
>         at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:29,347
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> @62000
> shutdown due to a local error: java.io.EOFException
> INFO   2015.01.10 14:00:29,383
> org.apache.activemq.network.DemandForwardingBridgeSupport -
> PERCMASTERBroker bridge to BALASSIBroker stopped
>
>
> After a few seconds the connection has been reestablished automatically:
>
> INFO   2015.01.10 14:00:45,563
> org.apache.activemq.broker.TransportConnection - Started responder end of
> duplex bridge clientConnector@ID:balaserver1-45698-1418680167169-1:1
> INFO   2015.01.10 14:00:45,570
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://PERCMASTERBroker#42 and tcp:///10.10.0.58:54625
> @62000
> (BALASSIBroker) has been established.
>
> But after then the cpu usage goes up to 100% (effectively killed the
> application) and the log full of duplicate message errors:
>
> WARN   2015.01.10 14:00:46,599
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> - cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36636, 4
> WARN   2015.01.10 14:00:46,639 org.apache.activemq.broker.region.Queue -
> duplicate message from store
> ID:balaserver1-45698-1418680167169-6:1:2:1:36636, redirecting for dlq
> processing
> WARN   2015.01.10 14:00:48,526
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
> - cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36637, 4
> WARN   2015.01.10 14:00:48,528 org.apache.activemq.broker.region.Queue -
> duplicate message from store
> ID:balaserver1-45698-1418680167169-6:1:2:1:36637, redirecting for dlq
> processing
> WARN   2015.01.10 14:00:48,546
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:3,hasSpace:true
> - cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:3:1:37026, 4
> WARN   2015.01.10 14:00:48,547 org.apache.activemq.broker.region.Queue -
> duplicate message from store
> ID:balaserver1-45698-1418680167169-6:1:3:1:37026, redirecting for dlq
> processing
> WARN   2015.01.10 14:00:48,560
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
> - cursor got duplicate: ID:balaserver1-45698-1418680167169-6:1:2:1:36638, 4
>
> The only thing we could do is stop the application (on all nodes), clear
> the activemq-data folder and restart the application.
> When we simply tried to restart it, the startup process has stucked with no
> error message, just using 100% of the CPU.
>
> Do you have any idea what could have happened here?
>
> Thanks,
>
> Zoltan Nyari
>



--

Founder/CEO Spinn3r.com
Location: *San Francisco, CA*
blog: http://burtonator.wordpress.com
… or check out my Google+ profile
<https://plus.google.com/102718274791889610666/posts>
<http://spinn3r.com>
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Tim Bain
If you haven't configured the broker to write a GC log, you can find out if
you're doing full GCs by either attaching JConsole and looking at the
Memory tab or by using the jstat -gc command.  Both of those are only
options if you haven't killed the process, so they probably won't help you
now.

For what it's worth, I don't think Kevin's right about this being caused by
continual full GCs.  It's quite possible that a single full GC was the root
cause of the disconnection that starts it all, but if the broker was doing
continual full GCs like Kevin guessed, I don't think it would have
successfully reconnected nor that you'd have seen all the log lines about
duplicate messages.  I think it's more likely that there's another bug
related to how master/slave pairs handle network disconnection and
reconnection.

The log lines you posted look like they're from either the master or the
slave that gets disconnected; which is it, and is there anything useful in
the other's log?
On Jan 10, 2015 3:35 PM, "Kevin Burton" <[hidden email]> wrote:

> $100 says it’s spending all its time doing full GC. Look at your GC log..
> I bet it will keep printing “Full GC” constantly.
>
> Kevin
>
> On Sat, Jan 10, 2015 at 7:19 AM, Zoltán Nyári <[hidden email]>
> wrote:
>
> > Hi,
> >
> > We have an ActiveMQ multibroker network with 4 nodes. There is 1 master
> > node and 3 slave nodes,
> > every message is broadcasted between all nodes using persistent topics
> and
> > durable subscriptions.
> > ActiveMQ (version 5.9.1) is embedded into a Spring based Java Web
> > Application running on Tomcat 7.
> > It works well mostly, but today we had to face a serious issue for the
> > second time.
> >
> > The connection between the master node and a slave node is lost:
> >
> > WARN   2015.01.10 14:00:29,281
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> > exception processing local command
> > java.net.SocketException: Connection reset
> >         at
> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
> >         at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
> >         at
> >
> >
> org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:115)
> >         at java.io.DataOutputStream.flush(DataOutputStream.java:123)
> >         at
> >
> >
> org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:176)
> >         at
> >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
> >         at
> >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
> >         at
> >
> >
> org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
> >         at
> >
> >
> org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
> >         at
> >
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
> >         at
> >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
> >         at
> >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:29,335
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > INFO   2015.01.10 14:00:29,346
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.net.SocketException: Connection reset
> > INFO   2015.01.10 14:00:29,346
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > INFO   2015.01.10 14:00:29,346
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > INFO   2015.01.10 14:00:29,346
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > INFO   2015.01.10 14:00:29,347
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > WARN   2015.01.10 14:00:29,346
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> > exception processing local command
> > java.io.EOFException
> >         at java.io.DataInputStream.readFully(DataInputStream.java:197)
> >         at java.io.DataInputStream.readFully(DataInputStream.java:169)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightUnmarshalByteSequence(BaseDataStreamMarshaller.java:440)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.MessageMarshaller.tightUnmarshal(MessageMarshaller.java:72)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightUnmarshal(ActiveMQMessageMarshaller.java:66)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightUnmarshal(ActiveMQTextMessageMarshaller.java:66)
> >         at
> >
> >
> org.apache.activemq.openwire.OpenWireFormat.doUnmarshal(OpenWireFormat.java:371)
> >         at
> >
> >
> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:285)
> >         at
> >
> >
> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221)
> >         at
> >
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213)
> >         at
> > org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:29,347
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#30 and tcp:///10.10.0.58:40819
> > @62000
> > shutdown due to a local error: java.io.EOFException
> > INFO   2015.01.10 14:00:29,383
> > org.apache.activemq.network.DemandForwardingBridgeSupport -
> > PERCMASTERBroker bridge to BALASSIBroker stopped
> >
> >
> > After a few seconds the connection has been reestablished automatically:
> >
> > INFO   2015.01.10 14:00:45,563
> > org.apache.activemq.broker.TransportConnection - Started responder end of
> > duplex bridge clientConnector@ID:balaserver1-45698-1418680167169-1:1
> > INFO   2015.01.10 14:00:45,570
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://PERCMASTERBroker#42 and tcp:///10.10.0.58:54625
> > @62000
> > (BALASSIBroker) has been established.
> >
> > But after then the cpu usage goes up to 100% (effectively killed the
> > application) and the log full of duplicate message errors:
> >
> > WARN   2015.01.10 14:00:46,599
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> >
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> > - cursor got duplicate:
> ID:balaserver1-45698-1418680167169-6:1:2:1:36636, 4
> > WARN   2015.01.10 14:00:46,639 org.apache.activemq.broker.region.Queue -
> > duplicate message from store
> > ID:balaserver1-45698-1418680167169-6:1:2:1:36636, redirecting for dlq
> > processing
> > WARN   2015.01.10 14:00:48,526
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> >
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
> > - cursor got duplicate:
> ID:balaserver1-45698-1418680167169-6:1:2:1:36637, 4
> > WARN   2015.01.10 14:00:48,528 org.apache.activemq.broker.region.Queue -
> > duplicate message from store
> > ID:balaserver1-45698-1418680167169-6:1:2:1:36637, redirecting for dlq
> > processing
> > WARN   2015.01.10 14:00:48,546
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> >
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:3,hasSpace:true
> > - cursor got duplicate:
> ID:balaserver1-45698-1418680167169-6:1:3:1:37026, 4
> > WARN   2015.01.10 14:00:48,547 org.apache.activemq.broker.region.Queue -
> > duplicate message from store
> > ID:balaserver1-45698-1418680167169-6:1:3:1:37026, redirecting for dlq
> > processing
> > WARN   2015.01.10 14:00:48,560
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4ed7430a
> >
> :Consumer.PERCMASTER.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=1,cacheEnabled=true,maxBatchSize:2,hasSpace:true
> > - cursor got duplicate:
> ID:balaserver1-45698-1418680167169-6:1:2:1:36638, 4
> >
> > The only thing we could do is stop the application (on all nodes), clear
> > the activemq-data folder and restart the application.
> > When we simply tried to restart it, the startup process has stucked with
> no
> > error message, just using 100% of the CPU.
> >
> > Do you have any idea what could have happened here?
> >
> > Thanks,
> >
> > Zoltan Nyari
> >
>
>
>
> --
>
> Founder/CEO Spinn3r.com
> Location: *San Francisco, CA*
> blog: http://burtonator.wordpress.com
> … or check out my Google+ profile
> <https://plus.google.com/102718274791889610666/posts>
> <http://spinn3r.com>
>
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

nyariz
The log lines I posted are from the master side. The slave side log messages are also interesting:

INFO   2015.01.10 14:00:30,077 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#114 and tcp:///10.36.0.20:62000@40819 shutdown due to a local error: org.apache.activemq.transport.InactivityIOException: Channel was inactive for too (>30000) long: tcp://10.36.0.20:62000
INFO   2015.01.10 14:00:30,083 org.apache.activemq.network.DiscoveryNetworkConnector - Establishing network connection from vm://BALASSIBroker?async=false&network=true to tcp://10.36.0.20:62000
WARN   2015.01.10 14:00:30,185 org.apache.activemq.broker.TransportConnection - Failed to add Connection BALASSIBroker->PERCMASTERBroker-45698-1418680167169-14:2
javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
        at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
        at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:30,189 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#118 and tcp:///10.36.0.20:62000@54620 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
INFO   2015.01.10 14:00:30,197 org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker bridge to PERCMASTERBroker stopped
INFO   2015.01.10 14:00:31,192 org.apache.activemq.network.DiscoveryNetworkConnector - Establishing network connection from vm://BALASSIBroker?async=false&network=true to tcp://10.36.0.20:62000
WARN   2015.01.10 14:00:31,266 org.apache.activemq.broker.TransportConnection - Failed to add Connection BALASSIBroker->PERCMASTERBroker-45698-1418680167169-15:2
javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
        at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
        at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:31,273 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#122 and tcp:///10.36.0.20:62000@54621 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
INFO   2015.01.10 14:00:31,284 org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker bridge to PERCMASTERBroker stopped
INFO   2015.01.10 14:00:33,276 org.apache.activemq.network.DiscoveryNetworkConnector - Establishing network connection from vm://BALASSIBroker?async=false&network=true to tcp://10.36.0.20:62000
WARN   2015.01.10 14:00:33,345 org.apache.activemq.broker.TransportConnection - Failed to add Connection BALASSIBroker->PERCMASTERBroker-45698-1418680167169-16:2
javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
        at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
        at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:33,348 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#126 and tcp:///10.36.0.20:62000@54622 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
INFO   2015.01.10 14:00:33,356 org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker bridge to PERCMASTERBroker stopped
INFO   2015.01.10 14:00:37,352 org.apache.activemq.network.DiscoveryNetworkConnector - Establishing network connection from vm://BALASSIBroker?async=false&network=true to tcp://10.36.0.20:62000
WARN   2015.01.10 14:00:37,426 org.apache.activemq.broker.TransportConnection - Failed to add Connection BALASSIBroker->PERCMASTERBroker-45698-1418680167169-17:2
javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
        at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
        at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
        at org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
        at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:37,428 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#130 and tcp:///10.36.0.20:62000@54624 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client: clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already connected from vm://BALASSIBroker#116
INFO   2015.01.10 14:00:37,436 org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker bridge to PERCMASTERBroker stopped
INFO   2015.01.10 14:00:40,084 org.apache.activemq.network.DemandForwardingBridgeSupport - Network Could not shutdown in a timely manner
WARN   2015.01.10 14:00:40,091 org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an exception processing local command
java.net.SocketException: Socket closed
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
        at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96)
        at java.io.DataOutputStream.write(DataOutputStream.java:107)
        at org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
        at org.apache.activemq.openwire.v10.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182)
        at org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89)
        at org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightMarshal2(ActiveMQTextMessageMarshaller.java:89)
        at org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:243)
        at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:175)
        at org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
        at org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
        at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
        at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
        at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
        at org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
        at org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
        at org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
        at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
        at org.apache.activemq.transport.vm.VMTransport.doDispatch(VMTransport.java:138)
        at org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:127)
        at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:104)
        at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
        at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
        at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1365)
        at org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:884)
        at org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:930)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
INFO   2015.01.10 14:00:40,095 org.apache.activemq.broker.TransportConnector - Connector vm://BALASSIBroker stopped
INFO   2015.01.10 14:00:40,095 org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker bridge to PERCMASTERBroker stopped
INFO   2015.01.10 14:00:45,432 org.apache.activemq.network.DiscoveryNetworkConnector - Establishing network connection from vm://BALASSIBroker?async=false&network=true to tcp://10.36.0.20:62000
INFO   2015.01.10 14:00:45,433 org.apache.activemq.broker.TransportConnector - Connector vm://BALASSIBroker started
INFO   2015.01.10 14:00:45,505 org.apache.activemq.network.DemandForwardingBridgeSupport - Network connection between vm://BALASSIBroker#134 and tcp:///10.36.0.20:62000@54625 (PERCMASTERBroker) has been established.
WARN   2015.01.10 14:01:06,015 org.apache.activemq.broker.region.cursors.AbstractStoreCursor - org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea:Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true - cursor got duplicate: ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, 4
WARN   2015.01.10 14:01:06,017 org.apache.activemq.broker.region.Queue - duplicate message from store ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, redirecting for dlq processing
WARN   2015.01.10 14:01:06,071 org.apache.activemq.broker.region.cursors.AbstractStoreCursor - org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea:Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=false,size=1,cacheEnabled=true,maxBatchSize:1,hasSpace:true - cursor got duplicate: ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, 4
WARN   2015.01.10 14:01:06,072 org.apache.activemq.broker.region.Queue - duplicate message from store ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, redirecting for dlq processing

Thanks,
Zoltan
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Tim Bain
There are three things that happened here:

   1. Your master broker stopped sending messages to this slave for 30
   seconds.  (Did any other slaves experience a similar disconnect?)  This
   caused the slave to abort the connection.  This could happen due to network
   perturbations, but I'd expect both sides to time out their respective side
   of the connection, so that sounds less likely to me.  More likely is that
   something caused the master broker to stop responding for some reason; that
   could be an unidentified bug in the broker code, a long full garbage
   collect (or a continual series of them, like what Kevin Burton has
   observed), or some other OS performance bottleneck (maybe you're persisting
   messages to a file store that's on a disk that suddenly gets hit with lots
   of I/O contention, for example).  What actually caused the problem is hard
   to figure out after the fact but worth digging into if this starts
   happening repeatedly.  And I'd recommend that if it happens again, you
   check that full garbage collects aren't occurring, by using JConsole or
   jstat -gc, or by configuring GC logging on the broker's JVM.
   2. It appeared to take ~15 seconds for the master to disconnect the
   connection to the slave; in the meantime, it rejected the connection
   attempts because it thought the slave was still connected.  This would be
   even harder to figure out the root cause for, but it worked itself out
   quickly, so maybe that's OK.
   3. You got lots of messages that got treated as duplicates, which sounds
   a lot like https://issues.apache.org/jira/browse/AMQ-5274, which is
   fixed in the not-yet-released 5.11.0.  Does that bug description match your
   setup?  If so, you could either use a snapshot version right away or (if
   your organization will only let you use released versions of software) you
   can live with the bug for now and then upgrade to 5.11.0 when it gets
   released.  Or you could patch the fix onto your current broker version and
   use it right away, if your organization is comfortable with that sort of
   thing.

Tim

On Sun, Jan 11, 2015 at 10:49 AM, nyariz <[hidden email]> wrote:

> The log lines I posted are from the master side. The slave side log
> messages
> are also interesting:
>
> INFO   2015.01.10 14:00:30,077
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#114 and tcp:///10.36.0.20:62000
> @40819
> shutdown due to a local error:
> org.apache.activemq.transport.InactivityIOException: Channel was inactive
> for too (>30000) long: tcp://10.36.0.20:62000
> INFO   2015.01.10 14:00:30,083
> org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> network
> connection from vm://BALASSIBroker?async=false&network=true to
> tcp://10.36.0.20:62000
> WARN   2015.01.10 14:00:30,185
> org.apache.activemq.broker.TransportConnection - Failed to add Connection
> BALASSIBroker->PERCMASTERBroker-45698-1418680167169-14:2
> javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
>         at
>
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
>         at
>
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
>         at
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
>         at
>
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>         at
>
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:30,189
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#118 and tcp:///10.36.0.20:62000
> @54620
> shutdown due to a local error: javax.jms.InvalidClientIDException: Broker:
> BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
> INFO   2015.01.10 14:00:30,197
> org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> bridge to PERCMASTERBroker stopped
> INFO   2015.01.10 14:00:31,192
> org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> network
> connection from vm://BALASSIBroker?async=false&network=true to
> tcp://10.36.0.20:62000
> WARN   2015.01.10 14:00:31,266
> org.apache.activemq.broker.TransportConnection - Failed to add Connection
> BALASSIBroker->PERCMASTERBroker-45698-1418680167169-15:2
> javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
>         at
>
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
>         at
>
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
>         at
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
>         at
>
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>         at
>
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:31,273
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#122 and tcp:///10.36.0.20:62000
> @54621
> shutdown due to a local error: javax.jms.InvalidClientIDException: Broker:
> BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
> INFO   2015.01.10 14:00:31,284
> org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> bridge to PERCMASTERBroker stopped
> INFO   2015.01.10 14:00:33,276
> org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> network
> connection from vm://BALASSIBroker?async=false&network=true to
> tcp://10.36.0.20:62000
> WARN   2015.01.10 14:00:33,345
> org.apache.activemq.broker.TransportConnection - Failed to add Connection
> BALASSIBroker->PERCMASTERBroker-45698-1418680167169-16:2
> javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
>         at
>
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
>         at
>
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
>         at
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
>         at
>
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>         at
>
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:33,348
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#126 and tcp:///10.36.0.20:62000
> @54622
> shutdown due to a local error: javax.jms.InvalidClientIDException: Broker:
> BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
> INFO   2015.01.10 14:00:33,356
> org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> bridge to PERCMASTERBroker stopped
> INFO   2015.01.10 14:00:37,352
> org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> network
> connection from vm://BALASSIBroker?async=false&network=true to
> tcp://10.36.0.20:62000
> WARN   2015.01.10 14:00:37,426
> org.apache.activemq.broker.TransportConnection - Failed to add Connection
> BALASSIBroker->PERCMASTERBroker-45698-1418680167169-17:2
> javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
>         at
>
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
>         at
>
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
>         at
>
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
>         at
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
>         at
>
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>         at
>
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:37,428
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#130 and tcp:///10.36.0.20:62000
> @54624
> shutdown due to a local error: javax.jms.InvalidClientIDException: Broker:
> BALASSIBroker - Client:
> clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> connected from vm://BALASSIBroker#116
> INFO   2015.01.10 14:00:37,436
> org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> bridge to PERCMASTERBroker stopped
> INFO   2015.01.10 14:00:40,084
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network Could
> not shutdown in a timely manner
> WARN   2015.01.10 14:00:40,091
> org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> exception processing local command
> java.net.SocketException: Socket closed
>         at
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121)
>         at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
>         at
>
> org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96)
>         at java.io.DataOutputStream.write(DataOutputStream.java:107)
>         at
>
> org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
>         at
>
> org.apache.activemq.openwire.v10.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182)
>         at
>
> org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89)
>         at
>
> org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightMarshal2(ActiveMQTextMessageMarshaller.java:89)
>         at
>
> org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:243)
>         at
>
> org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:175)
>         at
>
> org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
>         at
>
> org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
>         at
>
> org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
>         at
>
> org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
>         at
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
>         at
>
> org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
>         at
>
> org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
>         at
>
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>         at
>
> org.apache.activemq.transport.vm.VMTransport.doDispatch(VMTransport.java:138)
>         at
> org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:127)
>         at
> org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:104)
>         at
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
>         at
>
> org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
>         at
>
> org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1365)
>         at
>
> org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:884)
>         at
>
> org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:930)
>         at
>
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
>         at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:745)
> INFO   2015.01.10 14:00:40,095
> org.apache.activemq.broker.TransportConnector
> - Connector vm://BALASSIBroker stopped
> INFO   2015.01.10 14:00:40,095
> org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> bridge to PERCMASTERBroker stopped
> INFO   2015.01.10 14:00:45,432
> org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> network
> connection from vm://BALASSIBroker?async=false&network=true to
> tcp://10.36.0.20:62000
> INFO   2015.01.10 14:00:45,433
> org.apache.activemq.broker.TransportConnector
> - Connector vm://BALASSIBroker started
> INFO   2015.01.10 14:00:45,505
> org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> connection between vm://BALASSIBroker#134 and tcp:///10.36.0.20:62000
> @54625
> (PERCMASTERBroker) has been established.
> WARN   2015.01.10 14:01:06,015
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> - cursor got duplicate:
> ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, 4
> WARN   2015.01.10 14:01:06,017 org.apache.activemq.broker.region.Queue -
> duplicate message from store
> ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, redirecting for dlq
> processing
> WARN   2015.01.10 14:01:06,071
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=false,size=1,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> - cursor got duplicate:
> ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, 4
> WARN   2015.01.10 14:01:06,072 org.apache.activemq.broker.region.Queue -
> duplicate message from store
> ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, redirecting for dlq
> processing
>
> Thanks,
> Zoltan
>
>
>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-embedded-broker-100-cpu-usage-tp4689765p4689774.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Kevin Burton
BTW Tim.. thanks for all your feedback to all these posts.  :)

Kevin

On Mon, Jan 12, 2015 at 7:41 AM, Tim Bain <[hidden email]> wrote:

> There are three things that happened here:
>
>    1. Your master broker stopped sending messages to this slave for 30
>    seconds.  (Did any other slaves experience a similar disconnect?)  This
>    caused the slave to abort the connection.  This could happen due to
> network
>    perturbations, but I'd expect both sides to time out their respective
> side
>    of the connection, so that sounds less likely to me.  More likely is
> that
>    something caused the master broker to stop responding for some reason;
> that
>    could be an unidentified bug in the broker code, a long full garbage
>    collect (or a continual series of them, like what Kevin Burton has
>    observed), or some other OS performance bottleneck (maybe you're
> persisting
>    messages to a file store that's on a disk that suddenly gets hit with
> lots
>    of I/O contention, for example).  What actually caused the problem is
> hard
>    to figure out after the fact but worth digging into if this starts
>    happening repeatedly.  And I'd recommend that if it happens again, you
>    check that full garbage collects aren't occurring, by using JConsole or
>    jstat -gc, or by configuring GC logging on the broker's JVM.
>    2. It appeared to take ~15 seconds for the master to disconnect the
>    connection to the slave; in the meantime, it rejected the connection
>    attempts because it thought the slave was still connected.  This would
> be
>    even harder to figure out the root cause for, but it worked itself out
>    quickly, so maybe that's OK.
>    3. You got lots of messages that got treated as duplicates, which sounds
>    a lot like https://issues.apache.org/jira/browse/AMQ-5274, which is
>    fixed in the not-yet-released 5.11.0.  Does that bug description match
> your
>    setup?  If so, you could either use a snapshot version right away or (if
>    your organization will only let you use released versions of software)
> you
>    can live with the bug for now and then upgrade to 5.11.0 when it gets
>    released.  Or you could patch the fix onto your current broker version
> and
>    use it right away, if your organization is comfortable with that sort of
>    thing.
>
> Tim
>
> On Sun, Jan 11, 2015 at 10:49 AM, nyariz <[hidden email]>
> wrote:
>
> > The log lines I posted are from the master side. The slave side log
> > messages
> > are also interesting:
> >
> > INFO   2015.01.10 14:00:30,077
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#114 and tcp:///10.36.0.20:62000
> > @40819
> > shutdown due to a local error:
> > org.apache.activemq.transport.InactivityIOException: Channel was inactive
> > for too (>30000) long: tcp://10.36.0.20:62000
> > INFO   2015.01.10 14:00:30,083
> > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > network
> > connection from vm://BALASSIBroker?async=false&network=true to
> > tcp://10.36.0.20:62000
> > WARN   2015.01.10 14:00:30,185
> > org.apache.activemq.broker.TransportConnection - Failed to add Connection
> > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-14:2
> > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> >         at
> >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> >         at
> >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> >         at
> > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:30,189
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#118 and tcp:///10.36.0.20:62000
> > @54620
> > shutdown due to a local error: javax.jms.InvalidClientIDException:
> Broker:
> > BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> > INFO   2015.01.10 14:00:30,197
> > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> > bridge to PERCMASTERBroker stopped
> > INFO   2015.01.10 14:00:31,192
> > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > network
> > connection from vm://BALASSIBroker?async=false&network=true to
> > tcp://10.36.0.20:62000
> > WARN   2015.01.10 14:00:31,266
> > org.apache.activemq.broker.TransportConnection - Failed to add Connection
> > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-15:2
> > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> >         at
> >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> >         at
> >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> >         at
> > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:31,273
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#122 and tcp:///10.36.0.20:62000
> > @54621
> > shutdown due to a local error: javax.jms.InvalidClientIDException:
> Broker:
> > BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> > INFO   2015.01.10 14:00:31,284
> > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> > bridge to PERCMASTERBroker stopped
> > INFO   2015.01.10 14:00:33,276
> > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > network
> > connection from vm://BALASSIBroker?async=false&network=true to
> > tcp://10.36.0.20:62000
> > WARN   2015.01.10 14:00:33,345
> > org.apache.activemq.broker.TransportConnection - Failed to add Connection
> > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-16:2
> > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> >         at
> >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> >         at
> >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> >         at
> > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:33,348
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#126 and tcp:///10.36.0.20:62000
> > @54622
> > shutdown due to a local error: javax.jms.InvalidClientIDException:
> Broker:
> > BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> > INFO   2015.01.10 14:00:33,356
> > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> > bridge to PERCMASTERBroker stopped
> > INFO   2015.01.10 14:00:37,352
> > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > network
> > connection from vm://BALASSIBroker?async=false&network=true to
> > tcp://10.36.0.20:62000
> > WARN   2015.01.10 14:00:37,426
> > org.apache.activemq.broker.TransportConnection - Failed to add Connection
> > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-17:2
> > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> >         at
> >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> >         at
> >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> >         at
> > org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:37,428
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#130 and tcp:///10.36.0.20:62000
> > @54624
> > shutdown due to a local error: javax.jms.InvalidClientIDException:
> Broker:
> > BALASSIBroker - Client:
> > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > connected from vm://BALASSIBroker#116
> > INFO   2015.01.10 14:00:37,436
> > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> > bridge to PERCMASTERBroker stopped
> > INFO   2015.01.10 14:00:40,084
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network Could
> > not shutdown in a timely manner
> > WARN   2015.01.10 14:00:40,091
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> > exception processing local command
> > java.net.SocketException: Socket closed
> >         at
> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121)
> >         at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
> >         at
> >
> >
> org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96)
> >         at java.io.DataOutputStream.write(DataOutputStream.java:107)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89)
> >         at
> >
> >
> org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightMarshal2(ActiveMQTextMessageMarshaller.java:89)
> >         at
> >
> >
> org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:243)
> >         at
> >
> >
> org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:175)
> >         at
> >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
> >         at
> >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
> >         at
> >
> >
> org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
> >         at
> >
> >
> org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
> >         at
> >
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
> >         at
> >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
> >         at
> >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> >         at
> >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >         at
> >
> >
> org.apache.activemq.transport.vm.VMTransport.doDispatch(VMTransport.java:138)
> >         at
> >
> org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:127)
> >         at
> > org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:104)
> >         at
> >
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
> >         at
> >
> >
> org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1365)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:884)
> >         at
> >
> >
> org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:930)
> >         at
> >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> >         at
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> >         at
> >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> >         at java.lang.Thread.run(Thread.java:745)
> > INFO   2015.01.10 14:00:40,095
> > org.apache.activemq.broker.TransportConnector
> > - Connector vm://BALASSIBroker stopped
> > INFO   2015.01.10 14:00:40,095
> > org.apache.activemq.network.DemandForwardingBridgeSupport - BALASSIBroker
> > bridge to PERCMASTERBroker stopped
> > INFO   2015.01.10 14:00:45,432
> > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > network
> > connection from vm://BALASSIBroker?async=false&network=true to
> > tcp://10.36.0.20:62000
> > INFO   2015.01.10 14:00:45,433
> > org.apache.activemq.broker.TransportConnector
> > - Connector vm://BALASSIBroker started
> > INFO   2015.01.10 14:00:45,505
> > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > connection between vm://BALASSIBroker#134 and tcp:///10.36.0.20:62000
> > @54625
> > (PERCMASTERBroker) has been established.
> > WARN   2015.01.10 14:01:06,015
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> >
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> > - cursor got duplicate:
> > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, 4
> > WARN   2015.01.10 14:01:06,017 org.apache.activemq.broker.region.Queue -
> > duplicate message from store
> > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, redirecting for
> dlq
> > processing
> > WARN   2015.01.10 14:01:06,071
> > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> >
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=false,size=1,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> > - cursor got duplicate:
> > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, 4
> > WARN   2015.01.10 14:01:06,072 org.apache.activemq.broker.region.Queue -
> > duplicate message from store
> > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, redirecting for
> dlq
> > processing
> >
> > Thanks,
> > Zoltan
> >
> >
> >
> > --
> > View this message in context:
> >
> http://activemq.2283324.n4.nabble.com/ActiveMQ-embedded-broker-100-cpu-usage-tp4689765p4689774.html
> > Sent from the ActiveMQ - User mailing list archive at Nabble.com.
> >
>



--

Founder/CEO Spinn3r.com
Location: *San Francisco, CA*
blog: http://burtonator.wordpress.com
… or check out my Google+ profile
<https://plus.google.com/102718274791889610666/posts>
<http://spinn3r.com>
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Tim Bain
I'm grateful for the help I get from the people on this list, so I'm happy
to offer what help I can in return.
On Jan 12, 2015 3:49 PM, "Kevin Burton" <[hidden email]> wrote:

> BTW Tim.. thanks for all your feedback to all these posts.  :)
>
> Kevin
>
> On Mon, Jan 12, 2015 at 7:41 AM, Tim Bain <[hidden email]> wrote:
>
> > There are three things that happened here:
> >
> >    1. Your master broker stopped sending messages to this slave for 30
> >    seconds.  (Did any other slaves experience a similar disconnect?)
> This
> >    caused the slave to abort the connection.  This could happen due to
> > network
> >    perturbations, but I'd expect both sides to time out their respective
> > side
> >    of the connection, so that sounds less likely to me.  More likely is
> > that
> >    something caused the master broker to stop responding for some reason;
> > that
> >    could be an unidentified bug in the broker code, a long full garbage
> >    collect (or a continual series of them, like what Kevin Burton has
> >    observed), or some other OS performance bottleneck (maybe you're
> > persisting
> >    messages to a file store that's on a disk that suddenly gets hit with
> > lots
> >    of I/O contention, for example).  What actually caused the problem is
> > hard
> >    to figure out after the fact but worth digging into if this starts
> >    happening repeatedly.  And I'd recommend that if it happens again, you
> >    check that full garbage collects aren't occurring, by using JConsole
> or
> >    jstat -gc, or by configuring GC logging on the broker's JVM.
> >    2. It appeared to take ~15 seconds for the master to disconnect the
> >    connection to the slave; in the meantime, it rejected the connection
> >    attempts because it thought the slave was still connected.  This would
> > be
> >    even harder to figure out the root cause for, but it worked itself out
> >    quickly, so maybe that's OK.
> >    3. You got lots of messages that got treated as duplicates, which
> sounds
> >    a lot like https://issues.apache.org/jira/browse/AMQ-5274, which is
> >    fixed in the not-yet-released 5.11.0.  Does that bug description match
> > your
> >    setup?  If so, you could either use a snapshot version right away or
> (if
> >    your organization will only let you use released versions of software)
> > you
> >    can live with the bug for now and then upgrade to 5.11.0 when it gets
> >    released.  Or you could patch the fix onto your current broker version
> > and
> >    use it right away, if your organization is comfortable with that sort
> of
> >    thing.
> >
> > Tim
> >
> > On Sun, Jan 11, 2015 at 10:49 AM, nyariz <[hidden email]>
> > wrote:
> >
> > > The log lines I posted are from the master side. The slave side log
> > > messages
> > > are also interesting:
> > >
> > > INFO   2015.01.10 14:00:30,077
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#114 and tcp:///10.36.0.20:62000
> > > @40819
> > > shutdown due to a local error:
> > > org.apache.activemq.transport.InactivityIOException: Channel was
> inactive
> > > for too (>30000) long: tcp://10.36.0.20:62000
> > > INFO   2015.01.10 14:00:30,083
> > > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > > network
> > > connection from vm://BALASSIBroker?async=false&network=true to
> > > tcp://10.36.0.20:62000
> > > WARN   2015.01.10 14:00:30,185
> > > org.apache.activemq.broker.TransportConnection - Failed to add
> Connection
> > > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-14:2
> > > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> > >         at
> > >
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > >         at
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> > >         at
> > >
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> > >         at
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> > >         at java.lang.Thread.run(Thread.java:745)
> > > INFO   2015.01.10 14:00:30,189
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#118 and tcp:///10.36.0.20:62000
> > > @54620
> > > shutdown due to a local error: javax.jms.InvalidClientIDException:
> > Broker:
> > > BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > > INFO   2015.01.10 14:00:30,197
> > > org.apache.activemq.network.DemandForwardingBridgeSupport -
> BALASSIBroker
> > > bridge to PERCMASTERBroker stopped
> > > INFO   2015.01.10 14:00:31,192
> > > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > > network
> > > connection from vm://BALASSIBroker?async=false&network=true to
> > > tcp://10.36.0.20:62000
> > > WARN   2015.01.10 14:00:31,266
> > > org.apache.activemq.broker.TransportConnection - Failed to add
> Connection
> > > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-15:2
> > > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> > >         at
> > >
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > >         at
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> > >         at
> > >
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> > >         at
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> > >         at java.lang.Thread.run(Thread.java:745)
> > > INFO   2015.01.10 14:00:31,273
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#122 and tcp:///10.36.0.20:62000
> > > @54621
> > > shutdown due to a local error: javax.jms.InvalidClientIDException:
> > Broker:
> > > BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > > INFO   2015.01.10 14:00:31,284
> > > org.apache.activemq.network.DemandForwardingBridgeSupport -
> BALASSIBroker
> > > bridge to PERCMASTERBroker stopped
> > > INFO   2015.01.10 14:00:33,276
> > > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > > network
> > > connection from vm://BALASSIBroker?async=false&network=true to
> > > tcp://10.36.0.20:62000
> > > WARN   2015.01.10 14:00:33,345
> > > org.apache.activemq.broker.TransportConnection - Failed to add
> Connection
> > > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-16:2
> > > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> > >         at
> > >
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > >         at
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> > >         at
> > >
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> > >         at
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> > >         at java.lang.Thread.run(Thread.java:745)
> > > INFO   2015.01.10 14:00:33,348
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#126 and tcp:///10.36.0.20:62000
> > > @54622
> > > shutdown due to a local error: javax.jms.InvalidClientIDException:
> > Broker:
> > > BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > > INFO   2015.01.10 14:00:33,356
> > > org.apache.activemq.network.DemandForwardingBridgeSupport -
> BALASSIBroker
> > > bridge to PERCMASTERBroker stopped
> > > INFO   2015.01.10 14:00:37,352
> > > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > > network
> > > connection from vm://BALASSIBroker?async=false&network=true to
> > > tcp://10.36.0.20:62000
> > > WARN   2015.01.10 14:00:37,426
> > > org.apache.activemq.broker.TransportConnection - Failed to add
> Connection
> > > BALASSIBroker->PERCMASTERBroker-45698-1418680167169-17:2
> > > javax.jms.InvalidClientIDException: Broker: BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:242)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.addConnection(ManagedRegionBroker.java:231)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:91)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> >
> org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:92)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:97)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.processAddConnection(TransportConnection.java:759)
> > >         at
> > >
> org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:139)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:145)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > >         at
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:247)
> > >         at
> > >
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> > >         at
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> > >         at java.lang.Thread.run(Thread.java:745)
> > > INFO   2015.01.10 14:00:37,428
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#130 and tcp:///10.36.0.20:62000
> > > @54624
> > > shutdown due to a local error: javax.jms.InvalidClientIDException:
> > Broker:
> > > BALASSIBroker - Client:
> > > clientConnector_PERCMASTERBroker_inbound_duplex_BALASSIBroker already
> > > connected from vm://BALASSIBroker#116
> > > INFO   2015.01.10 14:00:37,436
> > > org.apache.activemq.network.DemandForwardingBridgeSupport -
> BALASSIBroker
> > > bridge to PERCMASTERBroker stopped
> > > INFO   2015.01.10 14:00:40,084
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> Could
> > > not shutdown in a timely manner
> > > WARN   2015.01.10 14:00:40,091
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Caught an
> > > exception processing local command
> > > java.net.SocketException: Socket closed
> > >         at
> > > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121)
> > >         at
> java.net.SocketOutputStream.write(SocketOutputStream.java:159)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:96)
> > >         at java.io.DataOutputStream.write(DataOutputStream.java:107)
> > >         at
> > >
> > >
> >
> org.apache.activemq.openwire.v10.BaseDataStreamMarshaller.tightMarshalByteSequence2(BaseDataStreamMarshaller.java:431)
> > >         at
> > >
> > >
> >
> org.apache.activemq.openwire.v10.MessageMarshaller.tightMarshal2(MessageMarshaller.java:182)
> > >         at
> > >
> > >
> >
> org.apache.activemq.openwire.v10.ActiveMQMessageMarshaller.tightMarshal2(ActiveMQMessageMarshaller.java:89)
> > >         at
> > >
> > >
> >
> org.apache.activemq.openwire.v10.ActiveMQTextMessageMarshaller.tightMarshal2(ActiveMQTextMessageMarshaller.java:89)
> > >         at
> > >
> > >
> >
> org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:243)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:175)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.doOnewaySend(AbstractInactivityMonitor.java:304)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.oneway(AbstractInactivityMonitor.java:286)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:85)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:104)
> > >         at
> > >
> >
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.asyncRequest(ResponseCorrelator.java:81)
> > >         at
> > >
> > >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport.serviceLocalCommand(DemandForwardingBridgeSupport.java:968)
> > >         at
> > >
> > >
> >
> org.apache.activemq.network.DemandForwardingBridgeSupport$2.onCommand(DemandForwardingBridgeSupport.java:177)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.doDispatch(VMTransport.java:138)
> > >         at
> > >
> >
> org.apache.activemq.transport.vm.VMTransport.dispatch(VMTransport.java:127)
> > >         at
> > >
> org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:104)
> > >         at
> > >
> >
> org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
> > >         at
> > >
> > >
> >
> org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:1365)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:884)
> > >         at
> > >
> > >
> >
> org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:930)
> > >         at
> > >
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> > >         at
> > >
> >
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> > >         at
> > >
> > >
> >
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> > >         at java.lang.Thread.run(Thread.java:745)
> > > INFO   2015.01.10 14:00:40,095
> > > org.apache.activemq.broker.TransportConnector
> > > - Connector vm://BALASSIBroker stopped
> > > INFO   2015.01.10 14:00:40,095
> > > org.apache.activemq.network.DemandForwardingBridgeSupport -
> BALASSIBroker
> > > bridge to PERCMASTERBroker stopped
> > > INFO   2015.01.10 14:00:45,432
> > > org.apache.activemq.network.DiscoveryNetworkConnector - Establishing
> > > network
> > > connection from vm://BALASSIBroker?async=false&network=true to
> > > tcp://10.36.0.20:62000
> > > INFO   2015.01.10 14:00:45,433
> > > org.apache.activemq.broker.TransportConnector
> > > - Connector vm://BALASSIBroker started
> > > INFO   2015.01.10 14:00:45,505
> > > org.apache.activemq.network.DemandForwardingBridgeSupport - Network
> > > connection between vm://BALASSIBroker#134 and tcp:///10.36.0.20:62000
> > > @54625
> > > (PERCMASTERBroker) has been established.
> > > WARN   2015.01.10 14:01:06,015
> > > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> > >
> >
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> > > - cursor got duplicate:
> > > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, 4
> > > WARN   2015.01.10 14:01:06,017 org.apache.activemq.broker.region.Queue
> -
> > > duplicate message from store
> > > ID:Perc-Smartfront1-33556-1418679846629-5:1:2:1:19939, redirecting for
> > dlq
> > > processing
> > > WARN   2015.01.10 14:01:06,071
> > > org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> > > org.apache.activemq.broker.region.cursors.QueueStorePrefetch@61ee20ea
> > >
> >
> :Consumer.BALASSI.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=false,size=1,cacheEnabled=true,maxBatchSize:1,hasSpace:true
> > > - cursor got duplicate:
> > > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, 4
> > > WARN   2015.01.10 14:01:06,072 org.apache.activemq.broker.region.Queue
> -
> > > duplicate message from store
> > > ID:Perc-Smartfront1-33556-1418679846629-5:1:17:1:14867, redirecting for
> > dlq
> > > processing
> > >
> > > Thanks,
> > > Zoltan
> > >
> > >
> > >
> > > --
> > > View this message in context:
> > >
> >
> http://activemq.2283324.n4.nabble.com/ActiveMQ-embedded-broker-100-cpu-usage-tp4689765p4689774.html
> > > Sent from the ActiveMQ - User mailing list archive at Nabble.com.
> > >
> >
>
>
>
> --
>
> Founder/CEO Spinn3r.com
> Location: *San Francisco, CA*
> blog: http://burtonator.wordpress.com
> … or check out my Google+ profile
> <https://plus.google.com/102718274791889610666/posts>
> <http://spinn3r.com>
>
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

nyariz
In reply to this post by Tim Bain
Thanks for the detailed answer, the bug you linked seems interesting but I'm not sure it's relevant in this situation.

Unfortunately it happened again (the whole system collapsed), so I've got new information.

I think there might be something wrong with DLQ handling. One of the clients log is now full of the following messages:

WARN   2015.01.26 09:03:42,001 org.apache.activemq.store.kahadb.MessageDatabase - Duplicate message add attempt rejected. Destination: QUEUE://DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.HUNYADI.VirtualTopic.SFOperationShare, Message id: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592

WARN   2015.01.26 09:03:42,002 org.apache.activemq.broker.region.Queue - duplicate message from store ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, redirecting for dlq processing

WARN   2015.01.26 09:03:42,017 org.apache.activemq.broker.region.cursors.AbstractStoreCursor - org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4300a1f8:DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.CLOUD.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=62,cacheEnabled=true,maxBatchSize:200,hasSpace:true - cursor got duplicate: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, 4

WARN   2015.01.26 09:03:42,018 org.apache.activemq.broker.region.Queue - duplicate message from store ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, redirecting for dlq processing

WARN   2015.01.26 09:03:42,018 org.apache.activemq.broker.region.cursors.AbstractStoreCursor - org.apache.activemq.broker.region.cursors.QueueStorePrefetch@7eb8d136:DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.CLOUD.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=18,cacheEnabled=true,maxBatchSize:200,hasSpace:true - cursor got duplicate: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, 4
 
The interesting part is how can a queue named "DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.HUNYADI.VirtualTopic.SFOperationShare" can be created?
I tried to google it, but I haven't found anything like this.

Here is the broker configuration:

                BrokerService brokerService = new BrokerService();
                // http://activemq.apache.org/message-redelivery-and-dlq-handling.html
                brokerService.setSchedulerSupport(true);
                // set dead letter startegy
                IndividualDeadLetterStrategy idls = new IndividualDeadLetterStrategy();
                idls.setQueuePrefix("DLQ.");

                idls.setUseQueueForQueueMessages(true);
                idls.setUseQueueForTopicMessages(true);
                idls.setProcessNonPersistent(true);
                idls.setProcessExpired(false);
                idls.setEnableAudit(false);
                brokerService.setDestinationPolicy(new PolicyMap());
                PolicyEntry pe = new PolicyEntry();
                pe.setQueue(">");
                pe.setDeadLetterStrategy(idls);
                brokerService.getDestinationPolicy().setDefaultEntry(pe);

                // redelivery policy
                RedeliveryPlugin rdplugin = new RedeliveryPlugin();
                rdplugin.setFallbackToDeadLetter(true);
                rdplugin.setSendToDlqIfMaxRetriesExceeded(true);

                RedeliveryPolicy rdp = new RedeliveryPolicy();
                rdp.setInitialRedeliveryDelay(1000);
                rdp.setRedeliveryDelay(1000);
                rdp.setUseExponentialBackOff(false);
                rdp.setMaximumRedeliveries(2);

                rdplugin.getRedeliveryPolicyMap().setDefaultEntry(rdp); // for all cases
                brokerService.setPlugins(new BrokerPlugin[] { rdplugin });

Do you have any ideas?

Thanks,
Zoltan Nyari
Reply | Threaded
Open this post in threaded view
|

Re: ActiveMQ embedded broker 100% cpu usage

Tim Bain
Sorry for taking so long to respond to this.

Have you seen if you can reproduce this in 5.11.1?  A recent email by Gary
(in the past week) described two bugs that caused duplicate messages to be
delivered, both of which were fixed in 5.11.0, so I'd test whether getting
those fixes solves your problem.

As far as your queue name being prefixed with lots of "DLQ."s, I can only
assume that's a bug in the IndividualDeadLetterStrategy you've configured.
Do you see destinations by those names in the web console and/or JMX?  And
if so, do you see them only when you see this failover issue, or are these
two unrelated issues?

Tim
On Jan 26, 2015 2:57 AM, "nyariz" <[hidden email]> wrote:

> Thanks for the detailed answer, the bug you linked seems interesting but
> I'm
> not sure it's relevant in this situation.
>
> Unfortunately it happened again (the whole system collapsed), so I've got
> new information.
>
> I think there might be something wrong with DLQ handling. One of the
> clients
> log is now full of the following messages:
>
> WARN   2015.01.26 09:03:42,001
> org.apache.activemq.store.kahadb.MessageDatabase - Duplicate message add
> attempt rejected. Destination:
>
> QUEUE://DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.HUNYADI.VirtualTopic.SFOperationShare,
> Message id: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592
>
> WARN   2015.01.26 09:03:42,002 org.apache.activemq.broker.region.Queue -
> duplicate message from store ID:c-micro-1-46647-1421372713039-6:1:3:1:5592,
> redirecting for dlq processing
>
> WARN   2015.01.26 09:03:42,017
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@4300a1f8
> :DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.CLOUD.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=62,cacheEnabled=true,maxBatchSize:200,hasSpace:true
> - cursor got duplicate: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, 4
>
> WARN   2015.01.26 09:03:42,018 org.apache.activemq.broker.region.Queue -
> duplicate message from store ID:c-micro-1-46647-1421372713039-6:1:3:1:5592,
> redirecting for dlq processing
>
> WARN   2015.01.26 09:03:42,018
> org.apache.activemq.broker.region.cursors.AbstractStoreCursor -
> org.apache.activemq.broker.region.cursors.QueueStorePrefetch@7eb8d136
> :DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.CLOUD.VirtualTopic.SFOperationShare,batchResetNeeded=false,storeHasMessages=true,size=18,cacheEnabled=true,maxBatchSize:200,hasSpace:true
> - cursor got duplicate: ID:c-micro-1-46647-1421372713039-6:1:3:1:5592, 4
>
> The interesting part is how can a queue named
>
> "DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.DLQ.ActiveMQ.DLQ.Topic.Consumer.HUNYADI.VirtualTopic.SFOperationShare"
> can be created?
> I tried to google it, but I haven't found anything like this.
>
> Here is the broker configuration:
>
>                 BrokerService brokerService = new BrokerService();
>                 //
> http://activemq.apache.org/message-redelivery-and-dlq-handling.html
>                 brokerService.setSchedulerSupport(true);
>                 // set dead letter startegy
>                 IndividualDeadLetterStrategy idls = new
> IndividualDeadLetterStrategy();
>                 idls.setQueuePrefix("DLQ.");
>
>                 idls.setUseQueueForQueueMessages(true);
>                 idls.setUseQueueForTopicMessages(true);
>                 idls.setProcessNonPersistent(true);
>                 idls.setProcessExpired(false);
>                 idls.setEnableAudit(false);
>                 brokerService.setDestinationPolicy(new PolicyMap());
>                 PolicyEntry pe = new PolicyEntry();
>                 pe.setQueue(">");
>                 pe.setDeadLetterStrategy(idls);
>                 brokerService.getDestinationPolicy().setDefaultEntry(pe);
>
>                 // redelivery policy
>                 RedeliveryPlugin rdplugin = new RedeliveryPlugin();
>                 rdplugin.setFallbackToDeadLetter(true);
>                 rdplugin.setSendToDlqIfMaxRetriesExceeded(true);
>
>                 RedeliveryPolicy rdp = new RedeliveryPolicy();
>                 rdp.setInitialRedeliveryDelay(1000);
>                 rdp.setRedeliveryDelay(1000);
>                 rdp.setUseExponentialBackOff(false);
>                 rdp.setMaximumRedeliveries(2);
>
>                 rdplugin.getRedeliveryPolicyMap().setDefaultEntry(rdp); //
> for all cases
>                 brokerService.setPlugins(new BrokerPlugin[] { rdplugin });
>
> Do you have any ideas?
>
> Thanks,
> Zoltan Nyari
>
>
>
>
> --
> View this message in context:
> http://activemq.2283324.n4.nabble.com/ActiveMQ-embedded-broker-100-cpu-usage-tp4689765p4690398.html
> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>