How to detect slow responses in Umbraco API?

24/03/2020 by Piotr Bach - 3 min read

Introduction
Concept outline
Filter implementation
Using the filter
Configure appropriate log level
Final words

Introduction

In this short article, I am going to present a simple technique for detecting every slow response in Umbraco API with ActionFilters.

It can be very useful when you need to:

Find slow responses from the Umbraco API.
Apply an efficient micro-benchmark technique without fireworks for use in a short time.
Locate Umbraco CMS performance bottlenecks.
Fix integration issues.

Concept outline

The principle of operation is very simple - we need to create a custom class extending ActionFilterAttribute (called UmbracoApiPerformanceTrackingAttribute).

Then we need to intercept every action executing/executed events and measure the time between OnActionExecuting and OnActionExecutedAsync.

If the execution of the request takes longer than the assumed time, we should save detailed information to the log system for further diagnosis.

public sealed class UmbracoApiPerformanceTrackingAttribute : ActionFilterAttribute
{
   public override void OnActionExecuting(HttpActionContext actionContext)
   {
      //We start measuring the request

      base.OnActionExecuting(actionContext);
   }

   public override Task OnActionExecutedAsync(HttpActionExecutedContext actionExecutedContext, CancellationToken cancellationToken)
   {
      //We finish the measurement and log the information when the request is slow

      return base.OnActionExecutedAsync(actionExecutedContext, cancellationToken);
   }
}

Filter implementation

Inside the filter we should put the logic and add a few additional components:

Stopwatch object used for micro-benchmark enabling time measurement between OnActionExecuting and OnActionExecuted method.
HttpContext.Current.Items for short term Stopwatch storage.
Logger to save information about slow requests
Two configurable parameters: ProfilingModeEnabled and SlowResponseMinTimeInMilliseconds.

ProfilingModeEnabled flag allows you to turn the profiler on and off as needed.

SlowResponseMinTimeInMilliseconds defines the time of slow request because we want to log only suspicious requests.

public sealed class UmbracoApiPerformanceTrackingAttribute : ActionFilterAttribute
{
   private const string StopWatchCacheKey = "UmbracoPerformanceTracking_Stopwatch";

   public override void OnActionExecuting(HttpActionContext actionContext)
   {
      if (AppConfigProvider.ProfilingModeEnabled)
      {
         var stopwatch = Stopwatch.StartNew();

         HttpContext.Current.Items[StopWatchCacheKey] = stopwatch;
      }

      base.OnActionExecuting(actionContext);
   }

   public override Task OnActionExecutedAsync(HttpActionExecutedContext actionExecutedContext, CancellationToken cancellationToken)
   {
      if (AppConfigProvider.ProfilingModeEnabled)
      {
         Stopwatch stopwatch = (Stopwatch)HttpContext.Current.Items[StopWatchCacheKey];

         stopwatch.Stop();

         if (stopwatch.ElapsedMilliseconds >= AppConfigProvider.SlowResponseMinTimeInMilliseconds)
         {   
            Current.Logger.Warn(typeof(UmbracoCustomLoggingAttribute), $"SLOW RESPONSE (took more than {AppConfigProvider.SlowResponseMinTimeInMilliseconds}): {stopwatch.ElapsedMilliseconds} [ms] - {actionExecutedContext.Request.Method} {actionExecutedContext.Request.RequestUri}");
         }
      }

      return base.OnActionExecutedAsync(actionExecutedContext, cancellationToken);
   }
}

Using the filter

Once the attribute is ready, it's possible to decorate any UmbracoApiController with a new filter as follows:

[UmbracoApiPerformanceTracking]
public class SlowUmbracoApiController : UmbracoApiController
{
   public IHttpActionResult SlowEndpointA(string id)
   {
      return Json("Hello from Endpoint A");
   }

   public IHttpActionResult SlowEndpointB(string id)
   {
      return Json("Hello from Endpoint B");
   }
}

Thanks to this, every long-running request will be logged for future diagnosis. Naturally, you can put attributes on specific methods and log slow requests only for chosen endpoints. When using filters, we have a choice and flexibility.

Configure appropriate log level

Warning! If you run the site in a production environment, it is worth setting the appropriate login level. Keep logging level as high as possible to get better overall performance.

Umbraco 8 allows you to easily save logs using the popular Serilog library.

To set logging level to "Warning" and above with Serilog you need to:

Go to \config directory
Find serilog.config file and open the configuration file
Go to <appSettings> section
Set "serilog:minimum-level" value as "Warning" (serilog supports many log levels such as Verbose, Debug, Information, Warning, Error, Fatal)

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <appSettings>
        <!-- VALID Values: Verbose, Debug, Information, Warning, Error, Fatal -->
        <add key="serilog:minimum-level" value="Warning" />
    </appSettings>
</configuration>