[AMQ-4853] Advisory support leads to excessive CPU usage

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 5.9.0
• Fix Version/s: 5.9.1, 5.10.0
• Component/s: Broker
• Regression: Regression
• Assignee: Timothy A. Bish
• Reporter: Joshua Watkins
• Created: 06/Nov/13 17:47
• Updated: 21/Jan/15 20:34
• Resolved: 11/Nov/13 14:57

Description

After upgrading from AMQ 5.8 to 5.9 we have seen cpu usage continually climb until AMQ threads are taking nearly all of the CPU Resources while remaining fairly idle. This is just a single broker with advisory support on. (Advisory support is on in this case as we run the same config for a network of brokers.) Turning off advisory support reduced the CPU load to single digits.

top -H output:
Cpu(s): 97.8%us, 2.1%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 7872040k total, 6574324k used, 1297716k free, 301028k buffers
Swap: 0k total, 0k used, 0k free, 1635392k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
25476 root 16 0 2173m 891m 11m R 14.4 11.6 86:12.10 java
25472 root 15 0 2173m 891m 11m R 13.6 11.6 86:09.77 java
25155 root 16 0 2173m 891m 11m R 9.8 11.6 86:26.13 java
25471 root 16 0 2173m 891m 11m R 9.2 11.6 86:12.93 java
25514 root 16 0 2173m 891m 11m R 9.2 11.6 86:15.12 java
25202 root 16 0 2173m 891m 11m R 8.7 11.6 86:33.20 java
25189 root 16 0 2173m 891m 11m S 8.4 11.6 86:24.65 java
25274 root 16 0 2173m 891m 11m R 8.1 11.6 86:18.45 java
19272 root 15 0 2173m 891m 11m S 8.1 11.6 8:40.19 java
20039 root 15 0 2173m 891m 11m S 8.1 11.6 8:15.53 java
19270 root 15 0 2173m 891m 11m R 7.8 11.6 8:35.85 java
25134 root 16 0 2173m 891m 11m R 7.5 11.6 90:42.29 java
25259 root 15 0 2173m 891m 11m R 7.5 11.6 90:30.02 java
25474 root 16 0 2173m 891m 11m R 7.5 11.6 86:13.24 java
25475 root 16 0 2173m 891m 11m R 7.5 11.6 86:11.74 java
25483 root 16 0 2173m 891m 11m R 7.5 11.6 86:12.30 java
25210 root 15 0 2173m 891m 11m R 7.2 11.6 90:35.24 java
25129 root 16 0 2173m 891m 11m S 6.9 11.6 90:31.27 java
25249 root 16 0 2173m 891m 11m S 6.9 11.6 86:18.35 java
25489 root 16 0 2173m 891m 11m R 6.9 11.6 86:16.93 java
9971 root 15 0 2173m 891m 11m S 6.6 11.6 38:53.66 java
25116 root 16 0 2173m 891m 11m R 6.3 11.6 90:28.39 java
25513 root 16 0 2173m 891m 11m R 6.3 11.6 86:07.62 java

Thread dump snippets:

PID 25476 –
"ActiveMQ Transport: tcp:///10.33.154.95:48799@61616" daemon prio=10 tid=0x00002aaaf5288800 nid=0x6384 runnable [0x00000000489b1000]
java.lang.Thread.State: RUNNABLE
at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:346)
at org.apache.activemq.advisory.AdvisoryBroker.removeConsumer(AdvisoryBroker.java:270)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:137)
at org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:619)
at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:76)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:270)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
at java.lang.Thread.run(Thread.java:619)

PID - 25473
"ActiveMQ Transport: tcp:///10.33.154.95:48802@61616" daemon prio=10 tid=0x00002aaaf6afc800 nid=0x6381 runnable [0x000000004779f000]
java.lang.Thread.State: RUNNABLE
at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:346)
at org.apache.activemq.advisory.AdvisoryBroker.removeConsumer(AdvisoryBroker.java:270)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:137)
at org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:619)
at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:76)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:270)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
at java.lang.Thread.run(Thread.java:619)

PID 25471 –
"ActiveMQ Transport: tcp:///10.33.154.95:48803@61616" daemon prio=10 tid=0x00002aaaf6f4b800 nid=0x6380 runnable [0x00000000487af000]
java.lang.Thread.State: RUNNABLE
at java.util.concurrent.ConcurrentLinkedQueue.remove(ConcurrentLinkedQueue.java:346)
at org.apache.activemq.advisory.AdvisoryBroker.removeConsumer(AdvisoryBroker.java:270)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
at org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:137)
at org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:619)
at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:76)
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:292)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:270)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
at java.lang.Thread.run(Thread.java:619)