ActiveMQ
  1. ActiveMQ
  2. AMQ-3607

Setting OptimiseAcknowledge on a queue with a prefetch limit causes normal/fast consumers to miss messages when a slow consumer is blocking

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Not a Problem
    • Affects Version/s: 5.5.0
    • Fix Version/s: 5.6.0
    • Component/s: Broker
    • Labels:
      None
    • Environment:

      Java: 1.6.0_26-b03-383.jdk

      Description

      The attached test case tests slow consumer handling with a variety of topic policies and SessionFactory/ConnectionFactory settings. The expectation is that a normal (i.e. fast) consumer will continue to receive messages whilst a slow consumer is blocking.

      Without a prefetch limit, the expected behaviour is seen with setOptimizeAcknowledge both true and false.

      If a prefetch limit is set, setOptimizeAcknowledge(true) causes the normal/fast consumer to miss messages whilst the slow consumer is blocking.

      Would be nice to be able to turn on OptimiseAcknowledge for performance reasons, however it is also necessary to set the prefetch limit in order to trigger SlowConsumerStrategy/MessageEvictionStrategySupport logic.

      testDefaultSettings
      Publisher: Send 0
      SlowConsumer: Receive 0
      FastConsumer: Receive 0
      testDefaultSettings: Publisher Sent: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testDefaultSettings: Whilst slow consumer blocked:
      		- SlowConsumer Received: 1 [0]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testDefaultSettings: After slow consumer unblocked:
      		- SlowConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      
      testDefaultSettingsWithOptimiseAcknowledge
      testDefaultSettingsWithOptimiseAcknowledge: Publisher Sent: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testDefaultSettingsWithOptimiseAcknowledge: Whilst slow consumer blocked:
      		- SlowConsumer Received: 1 [0]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testDefaultSettingsWithOptimiseAcknowledge: After slow consumer unblocked:
      		- SlowConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      
      testBounded
      testBounded: Publisher Sent: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testBounded: Whilst slow consumer blocked:
      		- SlowConsumer Received: 1 [0]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testBounded: After slow consumer unblocked:
      		- SlowConsumer Received: 10 [0, 1, 2, 3, 4, 25, 26, 27, 28, 29]
      		- FastConsumer Received: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      
      testBoundedWithOptimiseAcknowledge
      testBoundedWithOptimiseAcknowledge: Publisher Sent: 30 [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]
      testBoundedWithOptimiseAcknowledge: Whilst slow consumer blocked:
      		- SlowConsumer Received: 1 [0]
      		- FastConsumer Received: 5 [0, 1, 2, 3, 4]
      testBoundedWithOptimiseAcknowledge: After slow consumer unblocked:
      		- SlowConsumer Received: 5 [0, 1, 2, 3, 4]
      		- FastConsumer Received: 5 [0, 1, 2, 3, 4]
      
      java.lang.AssertionError: Fast consumer missed messages whilst slow consumer was blocking expected:<[0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29]> but was:<[0, 1, 2, 3, 4]>
      

        Issue Links

          Activity

          Hide
          James Furness added a comment -

          Hi Gary,

          Thanks for your response. I see your point regards the low prefetch size:

          ActiveMQMessageConsumer.java
          if (ackCounter >= (info.getPrefetchSize() * .65) || (optimizeAcknowledgeTimeOut > 0 && System.currentTimeMillis() >= (optimizeAckTimestamp + optimizeAcknowledgeTimeOut))) {
          

          As expected, I can't get your modified test case passing (with 5.5.1-fuse-01-06), but will try again once your tweak to add the missing setter in ActiveMQConnectionFactory.configureConnection() is available.

          Cheers,
          James

          Show
          James Furness added a comment - Hi Gary, Thanks for your response. I see your point regards the low prefetch size: ActiveMQMessageConsumer.java if (ackCounter >= (info.getPrefetchSize() * .65) || (optimizeAcknowledgeTimeOut > 0 && System .currentTimeMillis() >= (optimizeAckTimestamp + optimizeAcknowledgeTimeOut))) { As expected, I can't get your modified test case passing (with 5.5.1-fuse-01-06), but will try again once your tweak to add the missing setter in ActiveMQConnectionFactory.configureConnection() is available. Cheers, James
          Hide
          Gary Tully added a comment -

          Great to see a nice junit test, I had to have a peek.
          Apart from the missing setter for connectionFactory.setOptimizeAcknowledgeTimeOut this test is working as expected.
          The failure results from the low prefetch and discard limit so more often than not messages are discarded and end up in the dlq.
          I made use of the setOptimizeAcknowledgeTimeOut feature, to allow an ack to be sent on a timer rather than on a percentage of prefetch such that there is more control in optimizeAck mode. Without that, once 5 messages are sent, the rest end up in the dlq as there is no ack till more are sent.
          If you enable debug logging for:
          org.apache.activemq.broker.region.TopicSubscription you will see the discards the result from the pending message limit strategy.

          Some mods in http://svn.apache.org/viewvc?rev=1208048&view=rev

          Show
          Gary Tully added a comment - Great to see a nice junit test, I had to have a peek. Apart from the missing setter for connectionFactory.setOptimizeAcknowledgeTimeOut this test is working as expected. The failure results from the low prefetch and discard limit so more often than not messages are discarded and end up in the dlq. I made use of the setOptimizeAcknowledgeTimeOut feature, to allow an ack to be sent on a timer rather than on a percentage of prefetch such that there is more control in optimizeAck mode. Without that, once 5 messages are sent, the rest end up in the dlq as there is no ack till more are sent. If you enable debug logging for: org.apache.activemq.broker.region.TopicSubscription you will see the discards the result from the pending message limit strategy. Some mods in http://svn.apache.org/viewvc?rev=1208048&view=rev
          Hide
          James Furness added a comment -

          Test case attached as requested

          Show
          James Furness added a comment - Test case attached as requested
          Hide
          Timothy Bish added a comment -

          Can you attach your test case as a file here and tick the Grant License to Apache box so that the test can be included in the source.

          Show
          Timothy Bish added a comment - Can you attach your test case as a file here and tick the Grant License to Apache box so that the test can be included in the source.

            People

            • Assignee:
              Gary Tully
              Reporter:
              James Furness
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development