Azure Service Bus SubscriptionClient high latency / not receiving messages concurrently

Question

If I send a batch of messages to a Topic, and read messages using a Subscription client, then I seem to receive messages sequentially, i.e. OnMessageAsync is fired for each message sent, however there is a noticeable (150+ millisecond) delay between each receive-event

Sender:

var factory = MessagingFactory.CreateFromConnectionString("blah");
sender = factory.CreateMessageSender("MyTopicName");

var tasks = new List<Task>();
for (int i = 0; i < 10; i++)
    tasks.Add(sender.SendAsync(new BrokeredMessage("My Message"))
       .ContinueWith(t => Log("Sent Message {i}"));

await Task.WhenAll(tasks);  // This completes within a few millis

Receiver:

receiver = factory.CreateSubscriptionClient("MyTopicName", "MySubscription");
_sbClient.OnMessageAsync(async message =>
{
    var msg = message.GetBody<string>();
    Log("Received message xxxx
    await message.CompleteAsync();
});

This means that the 10th message sent is only received more than 1.5 seconds after it was sent.

An Azure latency test shows about a 200ms latency to the datacenter I'm using, so I'm not expecting messages to come back before that (and indeed the first message is received shortly after this), however I wouldn't expect the 'cumulative' behavior I'm seeing.

Playing around with MaxConcurrentCalls and adding a delay in the OnMessageAsync, shows this working as expected, and I can see only MaxConcurrentCalls being processed at a time

I've messed around with DeleteOnReceive modes, enabling 'Express', disabling 'Partitioning', using AMQP rather than SBMP etc., however nothing really seems to make much difference.

[I'm Using Microsoft.ServiceBus, Version=3.0.0.0]

EDIT:
Here's what the log looks like. So if I send 10 messages at the same time, I'll only receive the 10th message 1.5 seconds after I sent it:

18:09:32.624 Sent message 0
18:09:32.624 Sent message 1
18:09:32.641 Sent message 2
18:09:32.641 Sent message 3
18:09:32.674 Sent message 4
18:09:32.674 Sent message 5
18:09:32.709 Sent message 6
18:09:32.709 Sent message 7
18:09:32.738 Sent message 8
18:09:32.738 Sent message 9

18:09:32.791 Received message 1 in 341 millis
18:09:32.950 Received message 2 in 487 millis
18:09:33.108 Received message 3 in 628 millis
18:09:33.265 Received message 4 in 770 millis
18:09:33.426 Received message 5 in 914 millis
18:09:33.586 Received message 6 in 1060 millis
18:09:33.745 Received message 7 in 1202 millis
18:09:33.906 Received message 8 in 1347 millis
18:09:34.065 Received message 9 in 1492 millis

Answer 1

After a bit of digging into how exactly the OnMessage message pump worked I realised that this is actually a polling mechanism, where the underlying call to ServiceBus is still a 'Receive()' that attempts to pull any new message(s). If that times out, the call is done again ad infinitum. The behaviour I was seeing then made sense if that call to Receive() only returned a single message, and then required a150ms roundtrip to retrieve the next one etc.

Enter the PrefetchCount. Setting this to a nonzero value on the SubscriptionClient effectively permits the underlying Receive() to pull down multiple messages, that are then cached and made (immediately) available for bubbling into OnMessage.

Answer 2

Basically you're processing messages much faster than Service Bus can deliver new ones. Azure SB is relatively slow on an individual-message basis. Verify this by adding a Task.Delay before completion and log the thread IDs, and you should see multiple copies spin up.