-
Bug
-
Resolution: Done
-
Major
-
1.2.0.CR4
-
None
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).