Uploaded image for project: 'ActiveMQ'
  1. ActiveMQ
  2. AMQ-6770

Slow events processing

Agile BoardAttach filesAttach ScreenshotVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Critical
    • Resolution: Duplicate
    • 5.14.5
    • None
    • JDBC
    • None
    • Patch

    Description

      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:

      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
      

      Output and result of execution attached.

      On database side there are information that execution of query is slow:

      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'
      

      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:

               findNextMessagesStatement = "SELECT ID, MSG FROM " + getFullMessageTableName()
                                              + " WHERE CONTAINER=? AND ID < ? AND ID > ? AND XID IS NULL ORDER BY ID LIMIT ?";
      

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

      Attachments

        Issue Links

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            jbonofre Jean-Baptiste Onofré
            ragnor84 Jakub
            Votes:
            1 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment