[QUERY] Azure Service Bus: Time Spent in Queue is Large

[punitganshani]

Library name and version

Azure.Messaging.ServiceBus

Query/Question

We have a .NET process where the process is subscribing to the Topic. One of the common observations is that the Time Spent in Queue is large.

Azure Service Bus is running with 2 Messaging Units. The usage of Service Bus is not high, but the messages are not being picked up. The Message Lock duration is 10-30 seconds for different queues.

The .NET code is running on AKS and is using Azure.Messaging.ServiceBus and the code appears like,

ServiceBusClient client = new ServiceBusClient("connectionString",new ServiceBusClientOptions());

ServiceBusProcessorOptions clientOptions = new ServiceBusProcessorOptions
            {
                AutoCompleteMessages = false
            };

ServiceBusProcessor processor = client.CreateProcessor("topicName", "subscription", clientOptions);

processor.ProcessMessageAsync += ProcessMessageHandler;
processor.ProcessErrorAsync += ProcessErrorHandler;

processor.StartProcessingAsync();

The time spent in queue is too much even if we run multiple pods. What is potential reason for the delay?

Environment

.NET SDK: Version: 8.0.300 Commit: 326f6e68b2 Workload version: 8.0.300-manifests.5273bb1c MSBuild version: 17.10.4+10fbfbf2e

Deployment running on Azure Kubernetes Service with Linux

[jsquire]

Hi @punitganshani. Thanks for reaching out and we regret that you're experiencing difficulties. The first thing that we'll want to do is understand what the client is seeing. To do so, we'll want to collect a 5-minute slice of verbose Azure SDK logs, filtered to the Azure-Messaging-ServiceBus event source. Examples for doing so can be found in the Diagnostics sample with further context and discussion in Logging with the Azure SDK for .NET.

It would also be helpful to instrument your message handler to capture:

• The current time (in UTC)
• The current time (in local)
• The start time for an invocation
• The end time for an invocation
• The enqueue time stamped on the message

The goal with the above is to understand how long it takes to process a message, how quickly messages are being returned from the service, and when those messages were enqueued. The SDK logs will also give us insight into any errors and implicit retries in the system and the raw service operations. Depending on what we see, we'll either have an understanding or we'll have data that suggests that the root is based in the service behavior.

Generally, these types of issues come down to a few common causes:

• The pod does not have enough network or CPU resources to maintain consistent throughput. This is often the case when setting higher concurrency for processing messages.
• The processing of messages is heavy and is not meeting your performance goals.
• There are errors in processing that are not being handled, leading to orphaned message locks, causing the service to delay resending.
• There's another reader using the entity that is taking locks and not completing messages.
• There are more messages in the entity than expected and the application is not processing quickly enough to outpace the incoming message traffic.

[github-actions[bot]]

Hi @punitganshani. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.