使用ActionFilter、自定义Middleware中间件记录请求耗时

一、业务需求描述

因前端接口请求响应较慢，故想在后端也记录一下接口或中间件请求耗时，通过全局记录，对部分较慢的接口进行优化

二、RequestTimeActionFilter

使用ActionFilter记录控制器接口（Action）执行耗时，步骤：
1.在执行【OnActionExecuting】时，创建一个【stopWatch】计时器对象，并将该对象存在【HttpContext】中。

2.在执行【OnActionExecuted】时，获取【HttpContext】中执行【OnActionExecuting】时存储的【stopWatch】计时器对象，并获取该对象中的【ElapsedMilliseconds 】属性，获取此次请求耗时。

3.创建一个【RequestTimeActionFilter.cs】类，并添加以下代码：

using Microsoft.AspNetCore.Mvc.Filters;
using System.Diagnostics;

namespace WebApp01.Filters
{
    public class RequestTimeActionFilter : IActionFilter
    {
        private readonly string key = "_responseKey";
        private readonly ILogger<RequestTimeActionFilter> _logger;

        public RequestTimeActionFilter(ILogger<RequestTimeActionFilter> logger)
        {
            this._logger = logger;
        }

        public void OnActionExecuted(ActionExecutedContext context)
        {
            //日志记录
            WriteLog(context);
        }

        public void OnActionExecuting(ActionExecutingContext context)
        {
            var stopWatch = new Stopwatch();
            context.HttpContext.Items[key] = stopWatch;
            stopWatch.Start();
        }
        /// <summary>
        /// 日志记录
        /// </summary>
        /// <param name="context"></param>
        private void WriteLog(ActionExecutedContext context)
        {
            //获取存在当前请求中的stopwatch对象
            Stopwatch stopwatch = (Stopwatch)context.HttpContext.Items[key];
            //获取由当前实例测量的总运行时间(以毫秒为单位)。
            //Gets the total elapsed time measured by the current instance, in milliseconds.
            double currentSeconds = stopwatch.ElapsedMilliseconds / 1000.0;
            string userName = context.HttpContext.User.Identity?.Name;
            //获取控制器相关参数
            //string controllerName = context.ActionDescriptor.RouteValues["controller"];
            //string actionName = context.ActionDescriptor.RouteValues["action"];
            //string accessPath = $"/api/{controllerName}/{actionName}";
            //当前访问的路径
            string accessPath = context.HttpContext.Request.Path;
            string res = $"{userName}({DateTime.Now})访问{accessPath} 接口耗时：【{currentSeconds}】秒";
            _logger.LogInformation(res);
        }

    }


}

4.在【Program.cs】中注入Filter

builder.Services.AddControllers(options =>
{
    options.Filters.Add<RequestTimeActionFilter>();//接口请求记录中间件
});

三、RequestTimeMiddleware

使用Middleware记录中间件执行耗时，步骤：
1.在执行【OnActionExecuting】时，创建一个【stopWatch】计时器对象，并将该对象存在【HttpContext】中。

2.在执行【OnActionExecuted】时，获取【HttpContext】中执行【OnActionExecuting】时存储的【stopWatch】计时器对象，并获取该对象中的【ElapsedMilliseconds 】属性，获取此次请求耗时。

3.创建一个【RequestTimeMiddleware.cs】类，并添加以下代码：

using System.Diagnostics;

namespace WebApp01.Middlewares
{
    public class RequestTimeMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly ILogger<RequestTimeMiddleware> _logger;
        public RequestTimeMiddleware(RequestDelegate next, ILogger<RequestTimeMiddleware> logger)
        {
            _next = next;
            this._logger = logger;
        }
        public Task InvokeAsync(HttpContext context)
        {
            //创建计时器对象，并开启计时
            var watch = new Stopwatch();
            watch.Start();
            context.Response.OnStarting(() => {
                // 停止计时
                watch.Stop();
                double currentSeconds = watch.ElapsedMilliseconds / 1000.0;
                WriteLog(context, currentSeconds);
                return Task.CompletedTask;
            });
            // 执行下一个中间件
            return this._next(context);
        }

        /// <summary>
        /// 日志记录
        /// </summary>
        /// <param name="context"></param>
        private void WriteLog(HttpContext context, double currentSeconds)
        {
            string userName = context.Request.HttpContext.User.Identity?.Name;
            string accessPath = context.Request.Path;
            string res = $"{userName}({DateTime.Now}) 访问路径：{accessPath}，RequestTimeMiddleware中间件执行耗时：【{currentSeconds}】秒";
            _logger.LogInformation(res);
        }
    }

}

4.在【Program.cs】中注入Middleware（在所有Middleware中间件之前注入，这样就会监控到执行完所有中间件后返回前端的耗时）

app.UseMiddleware<RequestTimeMiddleware>();

四、测试

1.在创建的WebApi项目中默认【WeatherForecastController.cs】控制器中调整以下代码：
（1）【GetWeatherForecast】为默认的接口，返回的是一个json。
（2）【GetSleepWeatherForecast】是新增的接口，在当前线程中sleep 1秒钟，用于测试Filter和中间件是否有正确记录

[ApiController]
    [Route("api/[controller]/[action]")]
    public class WeatherForecastController : ControllerBase
    {
        private static readonly string[] Summaries = new[]
        {
        "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching"
    };

        private readonly ILogger<WeatherForecastController> _logger;

        public WeatherForecastController(ILogger<WeatherForecastController> logger)
        {
            _logger = logger;
        }

        [HttpGet(Name = "GetWeatherForecast")]
        public IEnumerable<WeatherForecast> Get()
        {
            return Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = DateTime.Now.AddDays(index),
                TemperatureC = Random.Shared.Next(-20, 55),
                Summary = Summaries[Random.Shared.Next(Summaries.Length)]
            })
            .ToArray();
        }

        [HttpGet(Name = "GetSleepWeatherForecast")]
        public IEnumerable<WeatherForecast> GetSleep()
        {
            Thread.Sleep(1000);
            return Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = DateTime.Now.AddDays(index),
                TemperatureC = Random.Shared.Next(-20, 55),
                Summary = Summaries[Random.Shared.Next(Summaries.Length)]
            })
            .ToArray();
        }

    }

2.分别执行【swagger】中的【Get】和【GetSleep】接口，执行结果如下：
（1）“圈1”记录的是swagger的【index.html】和【swagger.json】的请求耗时
（2）“圈2”记录的是控制器【Get】接口在filter和middleware中的耗时。
（2）“圈3”记录的是控制器【GetSleep】接口在filter和middleware中的耗时。