How to detect slow responses via ActionFilterAttribute in Umbraco API

24/03/2020 by Piotr Bach

Introduction

In this short article I am going to present very simple technique to detect every slow responses 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 efficient technique without fireworks for use in a short time.

You should create UmbracoApiPerformanceTrackingAttribute class and intercept every action executing/executed events.

Inside the filter we have 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!

Happy Umbraco performance tracking!😉💨

References:

Similar articles: