activemq-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jakub (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (AMQ-6770) Slow events processing
Date Thu, 13 Jul 2017 05:10:01 GMT

     [ https://issues.apache.org/jira/browse/AMQ-6770?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Jakub updated AMQ-6770:
-----------------------
    Attachment: consumer-output.txt

> Slow events processing
> ----------------------
>
>                 Key: AMQ-6770
>                 URL: https://issues.apache.org/jira/browse/AMQ-6770
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: JDBC
>    Affects Versions: 5.14.5
>            Reporter: Jakub
>            Priority: Critical
>         Attachments: consumer-output.txt
>
>
> When ActiveMQ is configured with JDBC persistence storage (postgres) and there is many
pending events (more than 5 000 000) consumers receive events in a bulk only every several
seconds even if a queue contains a lot of events.
> To get such state of AMQ I've used activemq-perf-maven-plugin with below settings:
> {code}
> mvn org.apache.activemq.tooling:activemq-perf-maven-plugin:consumer -Dconsumer.destName=queue://TEST.FOO
-Dconsumer.recvDuration=300000 -Dconsumer.sessAckMode=tran
> sacted -DsysTest.reportType=verbose -DsysTest.numClients=3 -Dfactory.asyncSession=false
-Dfactory.prefetchQueue=1 -Dconsumer.sessTransacted=true -Dfactory.prefetchPolicy.queuePrefetch=1
> {code}
> Output and result of execution attached.
> On database side there are information that execution of query is slow:
> {code}
> 2017-07-13 04:37:38 UTC;activemq;11184;5966f908.2bb0;7/2253014;0;1;LOG:  duration: 7706.308
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:37:38 UTC;activemq;11184;5966f908.2bb0;7/2253014;0;2;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5583825'
> 2017-07-13 04:37:47 UTC;activemq;11184;5966f908.2bb0;7/2255501;0;3;LOG:  duration: 7921.731
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:37:47 UTC;activemq;11184;5966f908.2bb0;7/2255501;0;4;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5586325'
> 2017-07-13 04:37:56 UTC;activemq;6556;5966f907.199c;6/1900865;0;1;LOG:  duration: 8110.328
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:37:56 UTC;activemq;6556;5966f907.199c;6/1900865;0;2;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5588825'
> 2017-07-13 04:38:03 UTC;activemq;6556;5966f907.199c;6/1901366;0;3;LOG:  duration: 7711.928
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:03 UTC;activemq;6556;5966f907.199c;6/1901366;0;4;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5589325'
> 2017-07-13 04:38:11 UTC;activemq;2148;5966f359.864;2/2670600;0;3;LOG:  duration: 7737.924
ms  execute S_5: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:11 UTC;activemq;2148;5966f359.864;2/2670600;0;4;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5589825'
> 2017-07-13 04:38:20 UTC;activemq;2148;5966f359.864;2/2671104;0;5;LOG:  duration: 7750.932
ms  execute S_5: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:20 UTC;activemq;2148;5966f359.864;2/2671104;0;6;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5590325'
> 2017-07-13 04:38:28 UTC;activemq;6556;5966f907.199c;6/1902887;0;5;LOG:  duration: 7718.725
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:28 UTC;activemq;6556;5966f907.199c;6/1902887;0;6;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5590825'
> 2017-07-13 04:38:35 UTC;activemq;11184;5966f908.2bb0;7/2259004;0;5;LOG:  duration: 7685.510
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:35 UTC;activemq;11184;5966f908.2bb0;7/2259004;0;6;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5591325'
> 2017-07-13 04:38:43 UTC;activemq;2148;5966f359.864;2/2672124;0;7;LOG:  duration: 7717.112
ms  execute S_5: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:43 UTC;activemq;2148;5966f359.864;2/2672124;0;8;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5591825'
> 2017-07-13 04:38:51 UTC;activemq;11184;5966f908.2bb0;7/2259996;0;7;LOG:  duration: 7717.112
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:51 UTC;activemq;11184;5966f908.2bb0;7/2259996;0;8;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5592325'
> 2017-07-13 04:38:59 UTC;activemq;11184;5966f908.2bb0;7/2260488;0;9;LOG:  duration: 7682.116
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:38:59 UTC;activemq;11184;5966f908.2bb0;7/2260488;0;10;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5592825'
> 2017-07-13 04:39:07 UTC;activemq;11184;5966f908.2bb0;7/2260989;0;11;LOG:  duration: 7718.309
ms  execute S_3: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:39:07 UTC;activemq;11184;5966f908.2bb0;7/2260989;0;12;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5593325'
> 2017-07-13 04:39:15 UTC;activemq;7472;5966e588.1d30;5/1987914;0;3;LOG:  duration: 7779.711
ms  execute S_5: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:39:15 UTC;activemq;7472;5966e588.1d30;5/1987914;0;4;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5594325'
> 2017-07-13 04:39:23 UTC;activemq;7472;5966e588.1d30;5/1988403;0;5;LOG:  duration: 7789.711
ms  execute S_5: SELECT ID, MSG FROM ACTIVEMQ_MSGS WHERE CONTAINER=$1 AND ID < $2 AND ID
> $3 AND XID IS NULL ORDER BY ID
> 2017-07-13 04:39:23 UTC;activemq;7472;5966e588.1d30;5/1988403;0;6;DETAIL:  parameters:
$1 = 'queue://TEST.FOO', $2 = '11786094', $3 = '5594825'
> {code}
> I've tried to improve performance on database side by creating new indexes but it hasn't
helped. The problem is in number of rows that the query returns (in may case more than 5 000
000).
> After analyzing AMQ code a fix for it seams easy. Only first _maxPageSize_ rows (in my
case 500) are used so rest of rows can be skipped and even not processed by database.
> I think that the _findNextMessagesStatement_ should be changed to:
> {code}
>          findNextMessagesStatement = "SELECT ID, MSG FROM " + getFullMessageTableName()
>                                         + " WHERE CONTAINER=? AND ID < ? AND ID >
? AND XID IS NULL ORDER BY ID LIMIT ?";
> {code}
> where the LIMIT is set to _maxPageSize_.
> What do you think about such change? Is it safe in context of data consistency and events
processing in ActiveMQ? I know that LIMIT may not be a solution for everybody 
> as it probably isn't supported by all databases.
> I also wonder why the range in query ID < $2 AND ID > $3 is so wide? 



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Mime
View raw message