[
https://issues.apache.org/jira/browse/AMQ-6770?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jean-Baptiste Onofré reassigned AMQ-6770:
-----------------------------------------
Assignee: Jean-Baptiste Onofré
> 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
> Assignee: Jean-Baptiste Onofré
> Priority: Critical
> Attachments: activemq-jdbc-store-limit.patch, 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 isn't supported by [all
> databases|https://stackoverflow.com/questions/1528604/how-universal-is-the-limit-statement-in-sql].
> There is _org.apache.activemq.store.jdbc.JDBCAdapter.limitQuery_ method that
> should modify query to limit amount of rows but it has valuable
> implementation only in _OracleJDBCAdapter_, for other databases the method
> doesn't modify a query so limit isn't added.
> I also wonder why the range in query ID < $2 AND ID > $3 is so wide?
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
