activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Tim Bain <tb...@alumni.duke.edu>
Subject Re: ActiveMQ embedded broker 100% cpu usage
Date Mon, 12 Jan 2015 15:41:36 GMT
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 <nyari.zoltan@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.
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message