How to detect slow responses in Umbraco API?

Introduction

In this short article, I am going to present a very simple technique to detect every slow response coming from UmbracoApiController using ActionFilterAttribute.

It can be useful when we want to:

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

Concept outline

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);
   }
}

As you can see - we should create UmbracoApiPerformanceTrackingAttribute class and intercept every action executing/executed events.

Additional ingredients

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.
  • Extra logging the body of Post request to get all important parameters coming. Logging the parameters is outside the scope of this article.
  • 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)
         {
            string bodyDetails = string.Empty;

            if (actionExecutedContext.Request.Method == HttpMethod.Post)
            {
               StringBuilder bodyBuilder = new StringBuilder();

               foreach (var arg in actionExecutedContext.ActionContext.ActionArguments)
               {
                  bodyBuilder.Append(arg.ToJsonString());
               }

               bodyDetails = $"Body: {bodyBuilder}";
            }

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

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

Now, you should be able to decorate UmbracoApiController with new filter as follows:

[UmbracoApiPerformanceTracking]
public class BaseUmbracoApiController : UmbracoApiController
{
}

Configure appropriate log level

In this case, we will set the level as "Warning".

When using serilog:

  • 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>

And that's it!

I hope you find this concept useful and you can adapt it to your needs. 

Happy Umbraco performance tracking!😉💨

References:

Comments
Leave a Comment