James Green created AMQ-4141:
--------------------------------
Summary: Semi-stuck queue until server restart
Key: AMQ-4141
URL: https://issues.apache.org/jira/browse/AMQ-4141
Project: ActiveMQ
Issue Type: Bug
Components: Broker
Affects Versions: 5.7.0, 5.5.0
Reporter: James Green
Priority: Critical
We have a single Stomp consumer being invoked via a schedule with ten-second
intervals to consume at most 200 messages with a one second network timeout.
The consumer subscribes to /queue/account_events on the localhost broker
("hub"). This broker is connected to from three external brokers which have
producers on them ("production servers").
What we see is a large built-up of messages on the remote brokers for this
queue, with a small number of messages pending on the hub. The messages are not
persistent and tend to be smallish (<1KB).
The consumer is literally sat waiting for the next available message. Under
"normal" conditions it spins up and consumes 200 messages at a pace of a few
msgs per second. Right at this moment it goes dozens of seconds without a
message then processes two-three inside 2 seconds.
The hub's web console is showing 91 pending, 1 consumer. If I click to browse
this queue, there are no messages. The counter for 91 has been "stuck" for some
time now.
The hub has been set at debug level but there is only very recent logs
recorded. A sample of them grepping for "account_events" shows activity such as:
2012-10-29 15:25:50,016 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:25:50,016 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:25:50,016 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-110
2012-10-29 15:25:50,020 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:25:52,134 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:25:52,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:25:52,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-112
2012-10-29 15:25:52,134 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:20,016 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:20,016 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:20,016 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-110
2012-10-29 15:26:20,017 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:22,134 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:22,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:22,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-110
2012-10-29 15:26:22,134 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:35,687 | DEBUG | Unregistering MBean
org.apache.activemq:BrokerName=hub,Type=Subscription,persistentMode=Non-Durable,destinationType=Queue,destinationName=account_events,clientId=account_events_receiver,consumerId=ID_billing-35190-1351511867558-2_1285_-1_1
| org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport:
tcp:///127.0.0.1:50560@61612
2012-10-29 15:26:35,687 | DEBUG | hub removing consumer:
ID:billing-35190-1351511867558-2:1285:-1:1 for destination:
queue://account_events | org.apache.activemq.broker.region.AbstractRegion |
ActiveMQ Transport: tcp:///127.0.0.1:50560@61612
2012-10-29 15:26:35,688 | DEBUG | queue://account_events remove sub:
QueueSubscription: consumer=ID:billing-35190-1351511867558-2:1285:-1:1,
destinations=1, dispatched=0, delivered=0, pending=0, lastDeliveredSeqId: 0,
dequeues: 26950, dispatched: 26950, inflight: 0 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///127.0.0.1:50560@61612
2012-10-29 15:26:35,688 | DEBUG | Unregistering MBean
org.apache.activemq:BrokerName=hub,Type=Producer,destinationType=Dynamic,clientId=account_events_receiver,producerId=ID_billing-35190-1351511867558-2_1285_-1_1
| org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport:
tcp:///127.0.0.1:50560@61612
2012-10-29 15:26:35,688 | DEBUG | Unregistering MBean
org.apache.activemq:BrokerName=hub,Type=Connection,ConnectorName=stomp,Connection=account_events_receiver
| org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport:
tcp:///127.0.0.1:50560@61612
2012-10-29 15:26:35,688 | DEBUG | bridging (hub -> drax)
ID:billing-35190-1351511867558-1:1:0:0:80197, consumer:
ID:billing-35190-1351511867558-9:1:1:1, destination
topic://ActiveMQ.Advisory.Consumer.Queue.account_events, brokerPath:
[ID:billing-35190-1351511867558-0:1], message: ActiveMQMessage {commandId = 0,
responseRequired = false, messageId =
ID:billing-35190-1351511867558-1:1:0:0:80197, originalDestination = null,
originalTransactionId = null, producerId =
ID:billing-35190-1351511867558-9:2:1:1, destination =
topic://ActiveMQ.Advisory.Consumer.Queue.account_events, transactionId = null,
expiration = 0, timestamp = 0, arrival = 0, brokerInTime = 1351524395688,
brokerOutTime = 1351524395688, correlationId = null, replyTo = null, persistent
= false, type = Advisory, priority = 0, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content = null,
marshalledProperties = null, dataStructure = RemoveInfo {commandId = 0,
responseRequired = false, objectId =
ID:billing-35190-1351511867558-2:1285:-1:1, lastDeliveredSequenceId = 0},
redeliveryCounter = 0, size = 1024, properties = {consumerCount=0,
originBrokerURL=tcp://0.0.0.0:61616,
originBrokerId=ID:billing-35190-1351511867558-0:1, originBrokerName=hub},
readOnlyProperties = false, readOnlyBody = false, droppable = false} |
org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
BrokerService[hub] Task-110
2012-10-29 15:26:35,689 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-112
2012-10-29 15:26:36,847 | DEBUG | Setting up new connection id:
ID:billing-35190-1351511867558-2:1304, address: tcp://127.0.0.1:50601, info:
ConnectionInfo {commandId = 0, responseRequired = true, connectionId =
ID:billing-35190-1351511867558-2:1304, clientId = account_events_receiver,
clientIp = null, userName = , password = *****, brokerPath = null,
brokerMasterConnector = false, manageable = false, clientMaster = true,
faultTolerant = false, failoverReconnect = false} |
org.apache.activemq.broker.TransportConnection | ActiveMQ Transport:
tcp:///127.0.0.1:50601@61612
2012-10-29 15:26:36,887 | DEBUG | hub adding consumer:
ID:billing-35190-1351511867558-2:1304:-1:1 for destination:
queue://account_events | org.apache.activemq.broker.region.AbstractRegion |
ActiveMQ Transport: tcp:///127.0.0.1:50601@61612
2012-10-29 15:26:36,888 | DEBUG | queue://account_events add sub:
QueueSubscription: consumer=ID:billing-35190-1351511867558-2:1304:-1:1,
destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 26950,
dispatched: 26950, inflight: 0 | org.apache.activemq.broker.region.Queue |
ActiveMQ Transport: tcp:///127.0.0.1:50601@61612
2012-10-29 15:26:36,888 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-112
2012-10-29 15:26:36,889 | DEBUG | bridging (hub -> drax)
ID:billing-35190-1351511867558-1:1:0:0:80200, consumer:
ID:billing-35190-1351511867558-9:1:1:1, destination
topic://ActiveMQ.Advisory.Consumer.Queue.account_events, brokerPath:
[ID:billing-35190-1351511867558-0:1], message: ActiveMQMessage {commandId = 0,
responseRequired = false, messageId =
ID:billing-35190-1351511867558-1:1:0:0:80200, originalDestination = null,
originalTransactionId = null, producerId =
ID:billing-35190-1351511867558-9:2:1:1, destination =
topic://ActiveMQ.Advisory.Consumer.Queue.account_events, transactionId = null,
expiration = 0, timestamp = 0, arrival = 0, brokerInTime = 1351524396889,
brokerOutTime = 1351524396889, correlationId = null, replyTo = null, persistent
= false, type = Advisory, priority = 0, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content = null,
marshalledProperties = null, dataStructure = ConsumerInfo {commandId = 3,
responseRequired = false, consumerId =
ID:billing-35190-1351511867558-2:1304:-1:1, destination =
queue://account_events, prefetchSize = 200, maximumPendingMessageLimit = 0,
browser = false, dispatchAsync = true, selector = null, subscriptionName =
null, noLocal = false, exclusive = false, retroactive = false, priority = 0,
brokerPath = null, optimizedAcknowledge = false, noRangeAcks = false,
additionalPredicate = null}, redeliveryCounter = 0, size = 1024, properties =
{consumerCount=1, originBrokerURL=tcp://0.0.0.0:61616,
originBrokerId=ID:billing-35190-1351511867558-0:1, originBrokerName=hub},
readOnlyProperties = false, readOnlyBody = false, droppable = false} |
org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
BrokerService[hub] Task-112
2012-10-29 15:26:50,017 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:50,017 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:50,017 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-110
2012-10-29 15:26:50,017 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:52,134 | DEBUG | queue://account_events expiring messages .. |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:52,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
2012-10-29 15:26:52,134 | DEBUG | account_events toPageIn: 91, Inflight: 0,
pagedInMessages.size 0, enqueueCount: 27041, dequeueCount: 26950 |
org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[hub] Task-110
2012-10-29 15:26:52,134 | DEBUG | queue://account_events expiring messages
done. | org.apache.activemq.broker.region.Queue | ActiveMQ Broker[hub] Scheduler
Around the time (cannot be certain, was not looking) of "breakage" a 10MB
message was produced on this hub for consumption by each of the "production
servers" via a topic. The heap memory rose from 100-200MB (normal) to 300-450MB
at this point before levelling off around 200MB. The number of threads actually
halved before rising to normal. It is unknown if this is a factor.
Each "production server" correctly shows one consumer when it is connected from
the hub.
Continuing observations - restarting AMQ on the hub - a flood (7,000+) of
messages have now arrived according to the web console and the consumer is
racing through them. The production servers have cleared through their backlog
having handed over to the hub.
Some help isolating this with narrower debugging would be appreciated!
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
