You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by Zoltán Nyári <ny...@smartfront.hu> on 2015/01/10 16:19:44 UTC
ActiveMQ embedded broker 100% cpu usage
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
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Tim Bain <tb...@alumni.duke.edu>.
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" <bu...@spinn3r.com> wrote:
> BTW Tim.. thanks for all your feedback to all these posts. :)
>
> Kevin
>
> On Mon, Jan 12, 2015 at 7:41 AM, Tim Bain <tb...@alumni.duke.edu> 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 <ny...@smartfront.hu>
> > 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>
>
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Kevin Burton <bu...@spinn3r.com>.
BTW Tim.. thanks for all your feedback to all these posts. :)
Kevin
On Mon, Jan 12, 2015 at 7:41 AM, Tim Bain <tb...@alumni.duke.edu> 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 <ny...@smartfront.hu>
> 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>
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Tim Bain <tb...@alumni.duke.edu>.
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" <ny...@smartfront.hu> 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.
>
Re: ActiveMQ embedded broker 100% cpu usage
Posted by nyariz <ny...@smartfront.hu>.
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.
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Tim Bain <tb...@alumni.duke.edu>.
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 <ny...@smartfront.hu> 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.
>
Re: ActiveMQ embedded broker 100% cpu usage
Posted by nyariz <ny...@smartfront.hu>.
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.
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Tim Bain <tb...@alumni.duke.edu>.
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" <bu...@spinn3r.com> 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 <ny...@smartfront.hu>
> 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>
>
Re: ActiveMQ embedded broker 100% cpu usage
Posted by Kevin Burton <bu...@spinn3r.com>.
$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 <ny...@smartfront.hu>
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>