Uploaded image for project: 'AMQ Interconnect'
  1. AMQ Interconnect
  2. ENTMQIC-2033

Interconnect not sending the close response under load

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 1.3.0.ER1
    • 1.2.0.CR4
    • Qpid Dispatch Router
    • None
    • Interconnect August Sprint

      When running the tests on the development environment, I noticed that some of the performance tests are failing because Interconnect seems to not be sending the close frame.

      In Maestro logs, the following exception is logged:

      WARN 06:59:28,864 org.maestro.worker.jms.JMSResourceUtil - Error closing the consumer: Timed Out Waiting for close response: AmqpConsumer

      Unknown macro: { ID}

      org.apache.qpid.jms.JmsOperationTimedOutException: Timed Out Waiting for close response: AmqpConsumer

      Unknown macro: { ID}

      at org.apache.qpid.jms.provider.amqp.AmqpAbstractResource.close(AmqpAbstractResource.java:117)
      at org.apache.qpid.jms.provider.amqp.AmqpConsumer.close(AmqpConsumer.java:86)
      at org.apache.qpid.jms.provider.amqp.AmqpProvider$7$1.processConsumerInfo(AmqpProvider.java:506)
      at org.apache.qpid.jms.meta.JmsConsumerInfo.visit(JmsConsumerInfo.java:261)
      at org.apache.qpid.jms.provider.amqp.AmqpProvider$7.run(AmqpProvider.java:463)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at java.lang.Thread.run(Thread.java:748)

      The issue seems to be specific to some scenarios with larger messages and high load. In the case of the log above, it was taken from the following scenario:

      Broker URL for test 33: amqp://<host>:5672/test.performance.queue?protocol=AMQP&durable=false&limitDestinations=100
      Test duration for test 33: 90s
      Parallel count for test 33: 100
      Message size for test 33: 10240
      Target rate for test 33: 0
      FCL for test 33: 0

      The interconnect instance was running on a VM running RHEL 7.5. It is a single IC instance and no broker was involved. The receiver reported an average rate of 24840 messages/sec in this scenario.

      The recorded latency percentiles for the test were:

      Latency Values
      Max Latency 1598463.0000 μs
      99.99ᵗʰ Percentile 1412095.0000 μs
      99.9ᵗʰ Percentile 1218559.0000 μs
      99ᵗʰ Percentile 1112063.0000 μs
      95ᵗʰ Percentile 1027071.0000 μs
      90ᵗʰ Percentile 983039.0000 μs
      50ᵗʰ Percentile 633855.0000 μs

      One thing to note is that this does not happen to all the connections, but only to a part on them. On this case, 37 workers did not receive the close frame (out of 100 running).

              gmurthy@redhat.com Ganesh Murthy
              opiske Otavio Piske
              Fernando Giorgetti Fernando Giorgetti
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated:
                Resolved: