We were able to figure out how to enable the logging within Active MQ
and filtered the logs just for messages pertaining to one queue.
Further to make it simpler to triage we reduced the number of consumers
to 1. From the ActiveMQ logs, we see the consumers are being removed.
Not sure if that is normal?, and then the pre/post dispatch line up with
when the consumer application receives the next message.
Any assistance would be greatly appreciated.
Consumer Logs - notice the delay of about 1.5 seconds between the end of
consumption of one message and the start of the next.
[DEBUG] 2024-01-25T12:31:14,653
[T24.MessageIntegration.DefaultMessageHandlerWarehouseInventory-1]
[messaging.MainMessageHandlerImpl] 01/25/2024 12:31:14 : Exiting
ACTIVEMQ - onMessage Time: 497ms
[DEBUG] 2024-01-25T12:31:16,059
[T24.MessageIntegration.DefaultMessageHandlerWarehouseInventory-1]
[messaging.T24DefaultMessageListenerContainer] Received message of type
[class org.apache.activemq.command.ActiveMQTextMessage] from consumer
[atomikosJmsMessageConsumerWrapper for ActiveMQMessageConsumer {
value=ID:apparml01t-35333-1706203725769-1:3:2:159, started=true }] of
session [ActiveMQSession
{id=ID:apparml01t-35333-1706203725769-1:3:2,started=true,closed=false}
java.lang.Object@5c51f04a]
Active MQ logs filtered by queue name.
2024-01-25 12:31:14,294 | INFO | Adding Producer: ProducerInfo
{commandId = 832337, responseRequired = true, producerId =
ID:atasagl04t-39527-1706179079531-25:1:143499:1, destination =
queue://T24.WAREHOUSEINVENTORY.IN, brokerPath = null, dispatchAsync =
false, windowSize = 0, sentCount = 0} |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:14,298 | INFO | Adding destination:
Queue:T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:14,302 | INFO | Adding destination:
Topic:ActiveMQ.Advisory.Producer.Queue.T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:14,683 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 0, force:false,
Inflight: 1, pagedInMessages.size 1, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3239, memUsage:2749, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,683 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 0, force:false,
Inflight: 1, pagedInMessages.size 1, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3239, memUsage:2749, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,799 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 0, force:false,
Inflight: 0, pagedInMessages.size 1, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3239, memUsage:2749, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,800 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=0, pending=0 toPageIn: 0, force:false,
Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3240, memUsage:0, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,901 | INFO | Removing Consumer: ConsumerInfo
{commandId = 1259, responseRequired = true, consumerId =
ID:apparml01t-35333-1706203725769-1:3:2:158, destination =
queue://T24.WAREHOUSEINVENTORY.IN, prefetchSize = 0,
maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
selector = null, clientId = ID:apparml01t-35333-1706203725769-0:3,
subscriptionName = null, noLocal = false, exclusive = false, retroactive
= false, priority = 0, brokerPath = null, optimizedAcknowledge = false,
noRangeAcks = false, additionalPredicate = null, networkConsumerIds =
null} | org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,949 | DEBUG | Unregistering MBean
org.apache.activemq:type=Broker,brokerName=amqarml01t-61618,destinationType=Queue,destinationName=T24.WAREHOUSEINVENTORY.IN,endpoint=Consumer,clientId=ID_apparml01t-35333-1706203725769-0_3,consumerId=ID_apparml01t-35333-1706203725769-1_3_2_158
| org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,949 | DEBUG | amqarml01t-61618 removing consumer:
ID:apparml01t-35333-1706203725769-1:3:2:158 for destination:
queue://T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,949 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN
remove sub: QueueSubscription:
consumer=ID:apparml01t-35333-1706203725769-1:3:2:158, destinations=1,
dispatched=0, delivered=0, pending=0, prefetch=0, prefetchExtension=0,
lastDeliveredSeqId: 1983483, dequeues: 3240, dispatched: 1227, inflight:
0, groups: 0 | org.apache.activemq.broker.region.Queue | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,950 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=0, memory=0%, size=0, pending=0 toPageIn: 0, force:false,
Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3240, memUsage:0, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,950 | INFO | Adding destination:
Topic:ActiveMQ.Advisory.Consumer.Queue.T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:14,995 | INFO | Adding Consumer: ConsumerInfo
{commandId = 1267, responseRequired = true, consumerId =
ID:apparml01t-35333-1706203725769-1:3:2:159, destination =
queue://T24.WAREHOUSEINVENTORY.IN, prefetchSize = 0,
maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
selector = null, clientId = ID:apparml01t-35333-1706203725769-0:3,
subscriptionName = null, noLocal = false, exclusive = false, retroactive
= false, priority = 0, brokerPath = null, optimizedAcknowledge = false,
noRangeAcks = false, additionalPredicate = null, networkConsumerIds =
null} | org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,004 | DEBUG | amqarml01t-61618 adding consumer:
ID:apparml01t-35333-1706203725769-1:3:2:159 for destination:
queue://T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,006 | INFO | Removing Producer: ProducerInfo
{commandId = 832060, responseRequired = true, producerId =
ID:atasagl04t-39527-1706179079531-25:1:143445:1, destination =
queue://T24.WAREHOUSEINVENTORY.IN, brokerPath = null, dispatchAsync =
false, windowSize = 0, sentCount = 1} |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:15,006 | DEBUG | Unregistering MBean
org.apache.activemq:type=Broker,brokerName=amqarml01t-61618,destinationType=Queue,destinationName=T24.WAREHOUSEINVENTORY.IN,endpoint=Producer,clientId=SendActiveMQA2A24T_A2A_Leg2_Non_105a,producerId=ID_atasagl04t-39527-1706179079531-25_1_143445_1
| org.apache.activemq.broker.jmx.ManagementContext | ActiveMQ Transport:
tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:15,007 | INFO | Adding destination:
Topic:ActiveMQ.Advisory.Producer.Queue.T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.57:59032@61618
2024-01-25 12:31:15,005 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN add
sub: QueueSubscription:
consumer=ID:apparml01t-35333-1706203725769-1:3:2:159, destinations=0,
dispatched=0, delivered=0, pending=0, prefetch=0, prefetchExtension=0,
dequeues: 3240, dispatched: 1227, inflight: 0 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,020 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=0, pending=0 toPageIn: 0, force:false,
Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3240, memUsage:0, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,069 | INFO | Adding destination:
Topic:ActiveMQ.Advisory.Consumer.Queue.T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,083 | INFO | Message Pull from:
ID:apparml01t-35333-1706203725769-0:3 on T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:15,083 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=0, pending=0 toPageIn: 0, force:false,
Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0,
enqueueCount: 3240, dequeueCount: 3240, memUsage:0, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:16,003 | INFO | Sending message: ActiveMQTextMessage
{commandId = 10223052, responseRequired = true, messageId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1:1, originalDestination
= null, originalTransactionId = null, producerId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1, destination =
queue://T24.WAREHOUSEINVENTORY.IN, transactionId = null, deliveryTime =
0, expiration = 1706203876986, timestamp = 1706203875986, arrival = 0,
brokerInTime = 0, brokerOutTime = 0, correlationId = null, replyTo =
null, persistent = true, type = null, priority = 4, groupID = null,
groupSequence = 0, targetConsumerId = null, compressed = false, userID =
null, content = org.apache.activemq.util.ByteSequence@592ca940,
marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 2765, properties = null, readOnlyProperties = false,
readOnlyBody = false, droppable = false, jmsXGroupFirstForConsumer =
false, text = <?xml version="1.0"?>
2024-01-25 12:31:16,003 | INFO | Adding destination:
Queue:T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.util.LoggingBrokerPlugin | ActiveMQ
Transport: tcp:///10.20.201.56:38238@61618
2024-01-25 12:31:16,003 | DEBUG | amqarml01t-61618 Message
ID:atasagl03t-37596-1705947236486-25:1:1749389:1:1 sent to
queue://T24.WAREHOUSEINVENTORY.IN |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.56:38238@61618
2024-01-25 12:31:16,004 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 1, force:false,
Inflight: 0, pagedInMessages.size 0, pagedInPendingDispatch.size 0,
enqueueCount: 3241, dequeueCount: 3240, memUsage:5530, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.56:38238@61618
2024-01-25 12:31:16,004 | INFO | preProcessDispatch: MessageDispatch
{commandId = 0, responseRequired = false, consumerId =
ID:apparml01t-35333-1706203725769-1:3:2:159, destination =
queue://T24.WAREHOUSEINVENTORY.IN, message = ActiveMQTextMessage
{commandId = 10223052, responseRequired = true, messageId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1:1, originalDestination
= null, originalTransactionId = null, producerId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1, destination =
queue://T24.WAREHOUSEINVENTORY.IN, transactionId = null, deliveryTime =
0, expiration = 1706203876986, timestamp = 1706203875986, arrival = 0,
brokerInTime = 1706203876003, brokerOutTime = 0, correlationId = null,
replyTo = null, persistent = true, type = null, priority = 4, groupID =
null, groupSequence = 0, targetConsumerId = null, compressed = false,
userID = null, content = org.apache.activemq.util.ByteSequence@2129fb,
marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 2765, properties = {BrokerPath=amqarml01t-61618},
readOnlyProperties = false, readOnlyBody = false, droppable = false,
jmsXGroupFirstForConsumer = false, text = <?xml version="1.0"?>
2024-01-25 12:31:16,059 | INFO | postProcessDispatch: MessageDispatch
{commandId = 0, responseRequired = false, consumerId =
ID:apparml01t-35333-1706203725769-1:3:2:159, destination =
queue://T24.WAREHOUSEINVENTORY.IN, message = ActiveMQTextMessage
{commandId = 10223052, responseRequired = true, messageId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1:1, originalDestination
= null, originalTransactionId = null, producerId =
ID:atasagl03t-37596-1705947236486-25:1:1749389:1, destination =
queue://T24.WAREHOUSEINVENTORY.IN, transactionId = null, deliveryTime =
0, expiration = 1706203876986, timestamp = 1706203875986, arrival = 0,
brokerInTime = 1706203876003, brokerOutTime = 1706203876059,
correlationId = null, replyTo = null, persistent = true, type = null,
priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@2129fb, marshalledProperties =
org.apache.activemq.util.ByteSequence@3cbb858e, dataStructure = null,
redeliveryCounter = 0, size = 2765, properties =
{BrokerPath=amqarml01t-61618}, readOnlyProperties = false, readOnlyBody
= false, droppable = false, jmsXGroupFirstForConsumer = false, text =
<?xml version="1.0"?>
2024-01-25 12:31:16,094 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 0, force:false,
Inflight: 1, pagedInMessages.size 1, pagedInPendingDispatch.size 0,
enqueueCount: 3241, dequeueCount: 3240, memUsage:2765, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
2024-01-25 12:31:16,104 | DEBUG | queue://T24.WAREHOUSEINVENTORY.IN,
subscriptions=1, memory=0%, size=1, pending=0 toPageIn: 0, force:false,
Inflight: 1, pagedInMessages.size 1, pagedInPendingDispatch.size 0,
enqueueCount: 3241, dequeueCount: 3240, memUsage:2765, maxPageSize:10 |
org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
tcp:///10.20.201.105:46782@61618
Thanks!
Steve.
On 1/24/24 1:02 PM, Arthur Naseef wrote:
Hello Steve. Your report is a little surprising because a 1-3 seconds
pause is huge. I'm curious under what conditions you see that latency - is
it only when running at full load?
Things that can be done to diagnose this down further:
1. View the broker's average enqueue time for messages in the queue - do
the two version of the broker show significantly different values for this
metric? (note this is less effective if a large backlog of messages ends
up sitting in the broker for longer).
2. Add logging in the broker with timing information for the messages
3. Use a test broker plugin that records the time the message is
received and the time it is dispatched to a consumer
4. Measure system performance (disk I/O, network I/O) and compare
between the runs
Questions that come to mind:
- How quickly are the messages consumed from the queues? I.E. is there
ever a backlog of messages in the queue, and if so, how big does it get for
both versions of the broker?
- How is the 1-3 second pause vs. instantaneous timing being meaused?
It is possible that default settings have changed, or additional
functionality was added that impacts performance.
BTW, is the messaging use-case that sensitive to latency?
Art
On Tue, Jan 23, 2024 at 8:58 AM Steve Hill <sh...@futurelogix.co.uk> wrote:
Hi:
We have successfully been using ActiveMQ Classic for many years.
Currently we are running ActiveMQ 5.15.4 and it successfully processes
millions of messages without issue. Our setup is fairly simple, we have
it operating in master/slave fashion utilizing shared storage in the
event ActiveMQ fails from one node to another.
Several years ago we attempted to upgrade to 5.16.x but ended up having
to remove it from production as we were seeing performance issues. We
have now attempted to upgrade to 5.18.3 and again are experiencing
delays; fortunately this time we caught it in our test environment!
This is consistent across applications that are consuming from the
queue's, we are seeing the initial time to retrieve the message from the
queue goes from near instantaneous on 5.15.4 to 1-3 second pause after
upgrading to 5.18.3. We make use of pooled connections to ActiveMQ,
depending on the queue there could be between 5 and 80 consumers. The
configuration is vanilla and the following policy is the largest change.
<policyEntry queue=">" enableAudit="false"
producerFlowControl="false" queuePrefetch="1" maxPageSize="10"
lazyDispatch="true" expireMessagesPeriod="600000">
</policyEntry>
Does anyone have any ideas about how we can diagnose the issue further;
we would really like to become current on the version of ActiveMQ we are
running.
Thanks!
Steve.
