Long delay from publish to consumer event

[boskjoett]

We are consistently, but with random frequency, experiencing long delays (more than a second) from the time a publisher delivers a message on the bus with BasicPublish() until a consumer (EventingBasicConsumer) is notified by a Received event.
We have tried both with and without auto-ack and using multiple consumers, but without any effect.
Our message bus is not overloaded, we can reproduce it with very few short messages.
We don't believe it is network delays because we can also reproduce the random delays in a docker-compose stack where both the producer, the consumer and RabbitMQ is running in containers in the same stack and the same docker network.
Has anybody experienced the same? Any good advice?

[lukebakken]

If you have a way to reproduce this using docker-compose, please share a repository that I can clone and run docker compose up on to see it.

Thanks!

[boskjoett]

The delay is consistently occurring for the first message sent to a queue. After the first message there are no significant delays. Why is the first message delivery always delayed? It seems like the bus has to be "warmed up". Same issue happens when the bus has been idle for some minutes. Is there some kind of "back-off" strategy in RabbitMQ causing the polling for messages to occur less frequently after an idle period?

[lukebakken]

No, not at all.

Everything described so far points to an application bug or environment issue. If delays like this were due to a bug or behavior in RabbitMQ or a client library we would hear about it every day from paying customers.

If I can reproduce this reliably I can explain it and fix it if necessary.

[lukebakken]

The delay is consistently occurring for the first message sent to a queue

Does this also include creating the connection? If so, you may be running into an issue with not enough threads in the thread pool. Eventually this problem will be addressed but it's how the C# client works for now.

https://github.com/rabbitmq/rabbitmq-dotnet-client/blob/main/projects/TestApplications/MassPublish/Program.cs#L21

[boskjoett]

No, the delay is not related to creation of the connection.

[lukebakken]

@boskjoett please see the following repo which contains a docker compose file that will bring up a .NET producer and consumer that communicate with RabbitMQ over TLS:

https://github.com/lukebakken/rabbitmq-dotnet-client-1060

When I run this code there is no delay in the first message.

Please compare my code with your environment to see what may be different. Ideally, you would fork my repository and make the changes necessary for me to see the same issue. Thanks.

[boskjoett]

I have forked your repo and simplified it to run outside docker. It also prints the message delay.
Repo link: https://github.com/boskjoett/rabbitmq-dotnet-client-1060

Output

CONSUMER: waiting 5 seconds to try initial connection
CONSUMER: waiting for messages...
CONSUMER received 09-16-2022 12:50:59.937  iteration 1 at 09-16-2022 12:50:59.975  - delay: 38,8116 ms
CONSUMER received 09-16-2022 12:51:04.977  iteration 2 at 09-16-2022 12:51:04.984  - delay: 7,5664 ms
CONSUMER received 09-16-2022 12:51:09.983  iteration 3 at 09-16-2022 12:51:09.985  - delay: 2,696 ms
CONSUMER received 09-16-2022 12:51:14.996  iteration 4 at 09-16-2022 12:51:15.000  - delay: 4,8325 ms
CONSUMER received 09-16-2022 12:51:20.013  iteration 5 at 09-16-2022 12:51:20.015  - delay: 2,8959 ms
CONSUMER received 09-16-2022 12:51:25.014  iteration 6 at 09-16-2022 12:51:25.016  - delay: 2,616 ms

Delivery of first message is 4 - 5 times as slow as the subsequent messages.

[lukebakken]

Thank you. Yes I see the same behavior running everything "natively" on Windows.

I'll compare with Linux, and I'll also do the same test using a Python consumer/producer.

[lukebakken]

Update - I see the same behavior on Linux running the .NET consumer/producer. I used the main branch of RabbitMQ, and nothing was running in docker.

So now I'm putting together the same test using Python/Pika.

[lukebakken]

Using Python, I don't see the same delay, so this must be due to something in the .NET library startup. Good find @boskjoett

Here's the Python branch - https://github.com/lukebakken/rabbitmq-dotnet-client-1060/tree/lukebakken/python

I'm working on the Docker bits still. Here is the output, however:

CONSUMER received 2022-09-16 08:56:02.910892 iteration 1 at now 2022-09-16 08:56:02.911383 - delay: 0:00:00.000491 ms
CONSUMER received 2022-09-16 08:56:07.916353 iteration 2 at now 2022-09-16 08:56:07.918335 - delay: 0:00:00.001982 ms
CONSUMER received 2022-09-16 08:56:12.917819 iteration 3 at now 2022-09-16 08:56:12.919781 - delay: 0:00:00.001962 ms
CONSUMER received 2022-09-16 08:56:17.919341 iteration 4 at now 2022-09-16 08:56:17.921335 - delay: 0:00:00.001994 ms
CONSUMER received 2022-09-16 08:56:22.925578 iteration 5 at now 2022-09-16 08:56:22.927424 - delay: 0:00:00.001846 ms

[lukebakken]

Obviously, @boskjoett if you have time to investigate that would be very much appreciated. Since I've been looking into this the issue of an initial delay seems more familiar, so there may be an old, closed issue in this repo where it was reported.

[lukebakken]

Please continue all discussion via this issue - #1252