How to detect slow responses in Umbraco API?
Table of contents
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:
Concept outline
The principle of the concept 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);
}
}API Filter implementation
Inside the filter we should put the logic and add a few additional components:
ProfilingModeEnabled flag allows you to turn the profiler on and off as needed.
SlowResponseMinTimeInMilliseconds defines the time of slow requests because we want to log only suspicious ones.
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
Umbraco 8 allows you to easily save logs using the popular Serilog library.
To set the logging level to "Warning" and above with Serilog you need to:
<?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>Final words
I hope you find this concept useful and you can adapt it to your needs.
Happy Umbraco performance tracking!😉💨
References:
