Measure ASP.NET Core 3.1 Web API action execution times

This is basically an unanswered code review request of mine from CodeReview Stack Exchange.

I want to be able to log as accurately as possible, the time spent by a certain Web API action in an ASP.NET Core 3.1 Web API.

I found out this very old question dealing with a similar issue in ASP.NET. The solution relies on global action filters, but in ASP.NET Core, I think middlewares are more appropriate.

From a client's perspective I want to measure as accurately as possible the following time:

Time to first byte - Time spent to send the request

So, using a slightly modified code from c-sharpcorner I have implemented the following:

/// <summary>
/// tries to measure request processing time
/// </summary>
public class ResponseTimeMiddleware
{
    // Name of the Response Header, Custom Headers starts with "X-"  
    private const string ResponseHeaderResponseTime = "X-Response-Time-ms";

    // Handle to the next Middleware in the pipeline  
    private readonly RequestDelegate _next;

    ///<inheritdoc/>
    public ResponseTimeMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    ///<inheritdoc/>
    public Task InvokeAsync(HttpContext context)
    {
        // skipping measurement of non-actual work like OPTIONS
        if (context.Request.Method == "OPTIONS")
            return _next(context);

        // Start the Timer using Stopwatch  
        var watch = new Stopwatch();
        watch.Start();

        context.Response.OnStarting(() => {
            // Stop the timer information and calculate the time   
            watch.Stop();
            var responseTimeForCompleteRequest = watch.ElapsedMilliseconds;
            // Add the Response time information in the Response headers.   
            context.Response.Headers[ResponseHeaderResponseTime] = responseTimeForCompleteRequest.ToString();

            var logger = context.RequestServices.GetService<ILoggingService>();
            string fullUrl = $"{context.Request.Scheme}://{context.Request.Host}{context.Request.Path}{context.Request.QueryString}";
            logger?.LogDebug($"[Performance] Request to {fullUrl} took {responseTimeForCompleteRequest} ms");

            return Task.CompletedTask;
        });

        // Call the next delegate/middleware in the pipeline   
        return _next(context);
    }
}

Startup.cs (plugging the middleware)

public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILoggerFactory loggerFactory,
    ILoggingService logger, IHostApplicationLifetime lifetime, IServiceProvider serviceProvider)
{
    app.UseResponseCaching();

    app.UseMiddleware<ResponseTimeMiddleware>();

    // ...
}

Is this a good approach? I am mostly interested in optimizing the following:

• time measurement accuracy
• overhead

posted about 4 years ago

CC BY-NC-SA 4.0

Alexei‭

5003 reputation 112 101 690 486