Large delay on PublishAsync

[rbarna1]

Hi. I'm running an ASPNetCore 2.0 app local in Docker with a Docker RabbitMq:latest image as well. There appears to be an odd delay occurring somewhere around the PublishAsync method, usually around 5-6 seconds. I instrumented some logging and as far as I can tell the actual execution of the PublishAsync task is very quick, just .11 seconds. So I cant explain the odd delay here.

The publish:

Logger.LogDebug($"Before: {DateTime.Now:O}\n");
await Wrap.ExecuteAsyncWithLogDuration(
  BusClient.PublishAsync(valueRequestToBePublished, ctx => ctx.UsePublishAcknowledge(false)), Logger);
Logger.LogDebug($"After: {DateTime.Now:O}\n");

The inner ExecuteAsyncWithLogDuration debugs...I added this in troubleshooting to get as close to the task execution as I possibly can where func is the BusClient.PublishAsync() call:

var stopwatch = Stopwatch.StartNew();
logger.LogDebug($"Wrap Before: {DateTime.Now:O}\n");
await func;
logger.LogDebug($"Wrap After: {DateTime.Now:O}\n");
logger.LogDebug($"Async Operation: {func} Duration: {stopwatch.Elapsed}. Completed: {func.IsCompleted}\n");

The logs:

Before: 2018-02-27T14:23:45.2131180+00:00

Wrap Before: 2018-02-27T14:23:52.2447271+00:00
Wrap After: 2018-02-27T14:23:52.3457419+00:00
Async Operation: System.Threading.Tasks.Task`1[RawRabbit.Pipe.IPipeContext] **Duration: 00:00:00.1148502**. Completed: True
After: 2018-02-27T14:23:52.3741668+00:00`

From the looks of it you'd almost think ExecuteAsyncWithLogDuration() was the problem since the 6+ seconds delay is between 'Before' and 'Wrap Before', but again I only added this wrap of PublishAsync because I'm trying to figure out why the overall PublishAsync is taking so long when rabbit itself seems quite healthy. Any thoughts?

[pardahlman]

Hi, @rbarna1 - as you say, the actual publish only takes a few milliseconds. The delay exists somewhere after ExecuteAsyncWithLogDuration returns and before the "after" logging entry is captured.

[rbarna1]

On the surface that would seem most likely, but it's not whats happening. Heres the entire method, where I test by commenting out one or the other task.
If I run just the 1ms sleep, the call from Postman into this Docker hosted ASPNetCore 2.0 container takes about 120ms in Release mode. If I run just the PublishAsync it takes about 7 seconds, also in Release mode.

        [HttpGet]
        public async Task<IActionResult> Get()
        {
            var valueRequestToBePublished = new ValueRequest
            {
                Value = Random.Next(1, 10)
            };

            await BusClient.PublishAsync(valueRequestToBePublished);
            await Task.Factory.StartNew(() => Thread.Sleep(1));
            return new OkObjectResult(new ValuesRequested()
            {
                NumberOfValues = valueRequestToBePublished.Value
            });
        }

[rbarna1]

To further illustrate the point I removed the subscription to this topic that was in this service (made no difference) and added a second publishAsync. It doubled the time to 12 seconds, so it's not some one time per request dll initialization or the like:

        [HttpGet]
        public async Task<IActionResult> Get()
        {
            var valueRequestToBePublished = new ValueRequest
            {
                Value = Random.Next(1, 10)
            };

            await BusClient.PublishAsync(valueRequestToBePublished);
            await BusClient.PublishAsync(valueRequestToBePublished);
            return new OkObjectResult(new ValuesRequested()
            {
                NumberOfValues = valueRequestToBePublished.Value
            });
        }

This reproduced on a colleagues machine as well with the same repo. Just for completeness sake here is my config and the VaueRequest attributes:

 "RawRabbit": {
    "Username": "guest",
    "Password": "guest",
    "VirtualHost": "/",
    "Port": 32780, //5672
    "Hostnames": ["172.17.0.1"],
    "RequestTimeout": "00:00:10",
    "PublishConfirmTimeout": "00:00:01",
    "RecoveryInterval": "00:00:10",
    "PersistentDeliveryMode": true,
    "AutoCloseConnection": true,
    "AutomaticRecovery": true,
    "TopologyRecovery": true,
    "Exchange": {
      "Durable": true,
      "AutoDelete": true,
      "Type": "Topic"
    },
    "Queue": {
      "AutoDelete": false,
      "Durable": true,
      "Exclusive": false
    }
  }

  [Exchange(Type = ExchangeType.Topic, Name = "phm.rabbitsample.exchange")]
  [Queue(Name = "phm.rabbitsample", Durable = true)]
  [Routing(RoutingKey = "phm.rabbitsample.key", NoAck = true, PrefetchCount = 50)]
  public class ValueRequest
  {
    public int Value { get; set; }
  }

[rbarna1]

Some update...the issue is with RabbitMQ in Docker. We took the same client and ran it against a Windows version of Rabbit as opposed to the MobyLinux Docker host version (both latest images), and the 5-6 second delay disappears. We're still researching what about running in Docker locally would cause this type of issue, will post back here if we discover root cause or any type of configuration that can mitigate.

[pardahlman]

Sounds good. I'm closing this for now, feel free to re-open if the issue is related to RR 😉