Steve - there's a lot of detail in there, so I'm not sure if I'm looking at
the right specifics.  I don't have a lot of time to dedicate to this right
now.

If short-lived consumers are being used, that is a definite anti-pattern to
solve; ActiveMQ, as with all JMS solutions - and most (all?) messaging
middleware - is based on long-lived connections and consumers.  Cycling
through consumers or connections definitely hurts performance, and can lead
to significant problems for the broker, and all its clients.

Can you perhaps take the basics of the application's messaging code and put
it into a minimal application of its own to help verify?  Also note that
there are many signs of short-lived consumers.  In the broker management
tools (web console, JMX, jolookia) you can see consumers and their
identifiers.  If those IDs are changing continually, that's bad.  Same for
the connections themselves.

As for why this might be different between broker versions - I'm not sure.
However, if it is a problem of short-lived consumers, I personally would
focus on fixing that first and then if the problem is resolved, I wouldn't
recommend to spend time tracking that down (as a business matter, at least
- I certainly welcome the technical effort and insight it could provide).

Here is a page on broker plugins:

https://activemq.apache.org/interceptors


Note there are 2 key parts to a plugin - the custom BrokerFilter that does
the actual work, and the BrokerPlugin that acts as a factory for the
BrokerFilter.

BTW, I recommend to avoid using broker plugins in production for the most
part.  It can be done, but the risks are high, and it makes getting support
even harder.  However, for the purposes of tracking down this performance
concern running in pre-production, it can be very helpful.

Art




On Thu, Jan 25, 2024 at 10:43 AM Steve Hill <sh...@futurelogix.co.uk> wrote:

> 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.
> >>
> >>
>
>

Reply via email to