Matt:
Thank you for taking the time to reply. We have been using ActiveMQ in
our environment for approximately 10 years, changes have been made over
that time to compensate for issues that we ran into. I suspect we
changed the maxPageSize due to memory issues we were seeing on an
earlier ActiveMQ instance, the prefetch was changed as we have many
consumers on a particular queue and with a high value it did not balance
the message consumption so it would effectively become single threaded.
We have performed more investigation and now believe the issue we
experience is as a result of using an XA transaction manager to manage
the commit/rollback during processing. The logs below are in reverse
order (e.g. newest log line at the top) however you can still stark
timing differences between running anything over 5.16.x compared with
previous versions on ActiveMQ. We checked the release notes and nothing
obvious jumps out but it would appear something changed (probably in
ancillary libraries that ActiveMQ uses) that caused a negative impact in
the time to commit a transaction.
The following observations were made using the stock configuration, only
change were to the port ActiveMQ is listening on and where the kahadb
directory resides. The Entering and Exiting ACTIVEMQ log message are the
first and last line of the onMeassage method. As you can see there is a
dramatic difference in time to when the message consumption starts
between the versions.
5.15.16 - 8ms between end and begin of next transaction.
[DEBUG] 2024-02-28T16:05:54,766
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[messaging.MainMessageHandlerImpl] 02/28/2024 04:05:54 : Entering
ACTIVEMQ - onMessage
[DEBUG] 2024-02-28T16:05:54,766
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[messaging.T24DefaultMessageListenerContainer] Received message of type
[class org.apache.activemq.command.ActiveMQTextMes
sage] from consumer [atomikosJmsMessageConsumerWrapper for
ActiveMQMessageConsumer {
value=ID:apparml02t-38483-1709154311533-1:14:14:11, started=true }] of
session [ActiveMQSession {id=ID:apparml02t-38483-170915
4311533-1:14:14,started=true,closed=false} java.lang.Object@562d9c9e]
[DEBUG] 2024-02-28T16:05:54,766
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.ActiveMQMessageConsumer] ackLater: sending: MessageAck
{commandId = 0, responseRequired = false, ackType = 0, co
nsumerId = ID:apparml02t-38483-1709154311533-1:14:14:11, firstMessageId
= ID:atasagl03t-45008-1707242832332-45:1:396:1:1, lastMessageId =
ID:atasagl03t-45008-1707242832332-45:1:396:1:1, destination = queue://24T
RACC.PRODUCT.IN, transactionId =
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393135343335343736313032383535,branchId=61707061726d6c3032745f746573745f626532373933],
messageCount = 1, poison
Cause = null}
[TRACE] 2024-02-28T16:05:54,766
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.ActiveMQMessageConsumer]
ID:apparml02t-38483-1709154311533-1:14:14:11 received message:
MessageDispatch {command
Id = 0, responseRequired = false, consumerId =
ID:apparml02t-38483-1709154311533-1:14:14:11, destination =
queue://24TRACC.PRODUCT.IN, message = ActiveMQTextMessage {commandId =
2367, responseRequired = true, me
ssageId = ID:atasagl03t-45008-1707242832332-45:1:396:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:atasagl03t-45008-1707242832332-45:1:396:1, destination =
queue://24TRACC.PRODUC
T.IN, transactionId = null, expiration = 0, timestamp = 1709072661812,
arrival = 0, brokerInTime = 1709072679692, brokerOutTime =
1709154354765, correlationId = null, replyTo = null, persistent = true,
type = nu
ll, priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@5dd038d3, marshalledProperties =
null, dataStructu
re = null, redeliveryCounter = 0, size = 0, properties = null,
readOnlyProperties = true, readOnlyBody = true, droppable = false,
jmsXGroupFirstForConsumer = false, text = <?xml version="1.0"?>
[DEBUG] 2024-02-28T16:05:54,764
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.TransactionContext]
TransactionContext{transactionId=XID:[1096044365,globalId=61707061726d6c3032745f746573745f62
65313730393135343335343736313032383535,branchId=61707061726d6c3032745f746573745f626532373933],connection=ActiveMQConnection
{id=ID:apparml02t-38483-1709154311533-1:14,clientId=ID:apparml02t-38483-1709154311533-0
:14,started=true}} started XA transaction
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393135343335343736313032383535,branchId=61707061726d6c3032745f746573745f626532373933]
[DEBUG] 2024-02-28T16:05:54,764
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.TransactionContext] Start: XID:
61707061726D6C3032745F746573745F6265313730393135343335343736313032383535:6170706
1726D6C3032745F746573745F626532373933, flags: TMNOFLAGS
[DEBUG] 2024-02-28T16:05:54,761
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.ActiveMQMessageConsumer] remove:
ID:apparml02t-38483-1709154311533-1:14:14:10, lastDeliveredSequenceId:
23513
[DEBUG] 2024-02-28T16:05:54,759
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.TransactionContext] Commit: XID:
61707061726D6C3032745F746573745F6265313730393135343335323636383032353632:617070
61726D6C3032745F746573745F626532353039, onePhase=true
[DEBUG] 2024-02-28T16:05:54,759
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.TransactionContext]
TransactionContext{transactionId=XID:[1096044365,globalId=61707061726d6c3032745f746573745f62
65313730393135343335323636383032353632,branchId=61707061726d6c3032745f746573745f626532353039],connection=ActiveMQConnection
{id=ID:apparml02t-38483-1709154311533-1:14,clientId=ID:apparml02t-38483-1709154311533-0
:14,started=true}} ended XA transaction
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393135343335323636383032353632,branchId=61707061726d6c3032745f746573745f626532353039]
[DEBUG] 2024-02-28T16:05:54,758
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[activemq.TransactionContext] End: XID:
61707061726D6C3032745F746573745F6265313730393135343335323636383032353632:617070617
26D6C3032745F746573745F626532353039, flags: TMSUCCESS
[DEBUG] 2024-02-28T16:05:54,758
[T24.MessageIntegration.DefaultMessageHandlerProduct-4]
[messaging.MainMessageHandlerImpl] 02/28/2024 04:05:54 : Exiting
ACTIVEMQ - onMessage Time: 2086ms
5.18.3 - 281ms between end and begin of next transaction.
[DEBUG] 2024-02-29T08:47:54,963
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[messaging.MainMessageHandlerImpl] 02/29/2024 08:47:54 : Entering
ACTIVEMQ - onMessage
[DEBUG] 2024-02-29T08:47:54,963
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[messaging.T24DefaultMessageListenerContainer] Received message of type
[class org.apache.activemq.command.ActiveMQText
Message] from consumer [atomikosJmsMessageConsumerWrapper for
ActiveMQMessageConsumer {
value=ID:apparml02t-39645-1709214402540-1:14:10:14, started=true }] of
session [ActiveMQSession {id=ID:apparml02t-39645-
1709214402540-1:14:10,started=true,closed=false} java.lang.Object@49694fdd]
[DEBUG] 2024-02-29T08:47:54,963
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.ActiveMQMessageConsumer] ackLater: sending: MessageAck
{commandId = 0, responseRequired = false, ackType = 0,
consumerId = ID:apparml02t-39645-1709214402540-1:14:10:14,
firstMessageId = ID:atasagl03t-45008-1707242832332-45:1:663:1:1,
lastMessageId = ID:atasagl03t-45008-1707242832332-45:1:663:1:1,
destination = queue
://24TRACC.PRODUCT.IN, transactionId =
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393231343437343730323035383037,branchId=61707061726d6c3032745f746573745f626535373335],
messageCount =
1, poisonCause = null}
[TRACE] 2024-02-29T08:47:54,963
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.ActiveMQMessageConsumer]
ID:apparml02t-39645-1709214402540-1:14:10:14 received message:
MessageDispatch {comm
andId = 0, responseRequired = false, consumerId =
ID:apparml02t-39645-1709214402540-1:14:10:14, destination =
queue://24TRACC.PRODUCT.IN, message = ActiveMQTextMessage {commandId =
3969, responseRequired = tr
ue, messageId = ID:atasagl03t-45008-1707242832332-45:1:663:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:atasagl03t-45008-1707242832332-45:1:663:1, destination = queue://24TRA
CC.PRODUCT.IN, transactionId = null, expiration = 0, timestamp =
1709072675378, arrival = 0, brokerInTime = 1709072693258, brokerOutTime
= 1709214474712, correlationId = null, replyTo = null, persistent = tru
e, type = null, priority = 4, groupID = null, groupSequence = 0,
targetConsumerId = null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@390a9101, marshalledProperties = nu
ll, dataStructure = null, redeliveryCounter = 0, size = 0, properties =
null, readOnlyProperties = true, readOnlyBody = true, droppable = false,
jmsXGroupFirstForConsumer = false, text = <?xml version="1.0"?>
[DEBUG] 2024-02-29T08:47:54,708
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.TransactionContext]
TransactionContext{transactionId=XID:[1096044365,globalId=61707061726d6c3032745f746573745
f6265313730393231343437343730323035383037,branchId=61707061726d6c3032745f746573745f626535373335],connection=ActiveMQConnection
{id=ID:apparml02t-39645-1709214402540-1:14,clientId=ID:apparml02t-39645-170921440
2540-0:14,started=true}} started XA transaction
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393231343437343730323035383037,branchId=61707061726d6c3032745f746573745f626535373335]
[DEBUG] 2024-02-29T08:47:54,708
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.TransactionContext] Start: XID:
61707061726D6C3032745F746573745F6265313730393231343437343730323035383037:6170
7061726D6C3032745F746573745F626535373335, flags: TMNOFLAGS
[DEBUG] 2024-02-29T08:47:54,701
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.ActiveMQMessageConsumer] remove:
ID:apparml02t-39645-1709214402540-1:14:10:13, lastDeliveredSequenceId:
24605
[DEBUG] 2024-02-29T08:47:54,694
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.TransactionContext] Commit: XID:
61707061726D6C3032745F746573745F6265313730393231343437303630333035333038:617
07061726D6C3032745F746573745F626535323430, onePhase=true
[DEBUG] 2024-02-29T08:47:54,694
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.TransactionContext]
TransactionContext{transactionId=XID:[1096044365,globalId=61707061726d6c3032745f746573745
f6265313730393231343437303630333035333038,branchId=61707061726d6c3032745f746573745f626535323430],connection=ActiveMQConnection
{id=ID:apparml02t-39645-1709214402540-1:14,clientId=ID:apparml02t-39645-170921440
2540-0:14,started=true}} ended XA transaction
XID:[1096044365,globalId=61707061726d6c3032745f746573745f6265313730393231343437303630333035333038,branchId=61707061726d6c3032745f746573745f626535323430]
[DEBUG] 2024-02-29T08:47:54,682
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[activemq.TransactionContext] End: XID:
61707061726D6C3032745F746573745F6265313730393231343437303630333035333038:617070
61726D6C3032745F746573745F626535323430, flags: TMSUCCESS
[DEBUG] 2024-02-29T08:47:54,682
[T24.MessageIntegration.DefaultMessageHandlerProduct-7]
[messaging.MainMessageHandlerImpl] 02/29/2024 08:47:54 : Exiting
ACTIVEMQ - onMessage Time: 3900ms
Thanks!
Steve.
On 2/27/24 10:13 PM, Matt Pavlovich wrote:
Hi Steve-
These settings are lower than the default and generally lead to degraded
consumer performance. Any reason you lowered the maxPageSize from 200 to 10?
What only allow 1 message prefetch— the default is 1,000?
Thanks,
Matt Pavlovich
On Jan 23, 2024, at 9:58 AM, Steve Hill <[email protected]> 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.
