App Service Performance

Why do all requests show with a 1 minute duration

When inheriting a solution, you learn quite a few things and try to fix some of them. This particular problem was impacting our monitoring and capability to find issues in the application.

Some of our background jobs were triggered every minute, and every request (and request duration in Application Insights) showed as a full 1 minute. Of course that skews the performance numbers quite a lot and makes identifying and troubleshooting slow requests a lot harder.

After some research by one of our tech leads, we managed to find the culprit. Since the code ran in a background service worker, the team in the past decided to manually start and track all dependency calls.

_telemetryClient.StartOperation<RequestTelemetry>(operationName);

Time to have a look at the manually tracking dependencies.

Alternatively, TelemetryClient provides the extension methods StartOperation and StopOperation, which can be used to manually track dependencies as shown in Outgoing dependencies tracking.

The general approach for custom dependency tracking is to:

  • Call the TelemetryClient.StartOperation (extension) method that fills the DependencyTelemetry properties that are needed for correlation and some other properties, like start, time stamp, and duration.
  • Set other custom properties on any other context you need.
  • Make a dependency call.
  • Stop the operation with StopOperation when it’s finished.
  • (Handle exceptions)

Everything was done fine, yet one very important call was missing:

_telemetryClient.StopOperation(operation);

Due to that reason, tracing was started when the background tasked triggered (every minute) and a new operation was started the next minute, resulting the process to log a 1 minute request day ind and out.

Licensed under CC BY-NC-SA 4.0; code samples licensed under MIT.
comments powered by Disqus
Built with Hugo - Based on Theme Stack designed by Jimmy