如何获得实际的请求执行时间

Question

鉴于以下中间件:

public class RequestDurationMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger<RequestDurationMiddleware> _logger;

    public RequestDurationMiddleware(RequestDelegate next, ILogger<RequestDurationMiddleware> logger)
    {
        _next = next;
        _logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        var watch = Stopwatch.StartNew();
        await _next.Invoke(context);
        watch.Stop();

        _logger.LogTrace("{duration}ms", watch.ElapsedMilliseconds);
    }
}

由于管道,它发生在管道结束之前并记录不同的时间:

WebApi.Middlewares.RequestDurationMiddleware 2018-01-10 15:00:16.372 -02:00 [Verbose]  382ms
Microsoft.AspNetCore.Server.Kestrel 2018-01-10 15:00:16.374 -02:00 [Debug]  Connection id ""0HLAO9CRJUV0C"" completed keep alive response.
Microsoft.AspNetCore.Hosting.Internal.WebHost 2018-01-10 15:00:16.391 -02:00 [Information]  "Request finished in 405.1196ms 400 application/json; charset=utf-8"

在这种情况下,如何从WebHost(示例中为405.1196ms)值捕获实际请求执行时间？我想将此值存储在数据库中或在其他地方使用它.

Answer 1

我认为这个问题非常有趣,所以我仔细研究了一下WebHost实际测量和显示请求时间的方法.底线是:既没有好的,也没有简单的方法来获取这些信息,而且一切都像是黑客.但如果你仍然感兴趣,请继续关注.

当应用程序启动时,WebHostBuilder构造WebHost它依次创建HostingApplication.这基本上是负责响应传入请求的根组件.它是在请求进入时调用中间件管道的组件.

它也是将创建的组件,HostingApplicationDiagnostics它允许收集有关请求处理的诊断信息.在请求开始时,HostingApplication将调用HostingApplicationDiagnostics.BeginRequest,并在请求结束时调用HostingApplicationDiagnostics.RequestEnd.

不足为奇的HostingApplicationDiagnostics是,它将衡量请求持续时间并记录WebHost您已经看到的消息.所以这是我们必须更密切地检查以确定如何获取信息的类.

有两件事,诊断对象用于报告诊断信息:记录器和a DiagnosticListener.

诊断听众

这DiagnosticListener是一个有趣的事情:它基本上是一个通用事件接收器,你可以只是举起事件.然后其他对象可以订阅它以收听这些事件.所以这对我们来说几乎听起来很完美!

用户传递的DiagnosticListener对象实际上是从依赖注入中解析的.因为它是作为单例注册的,所以我们实际上可以从依赖注入中解析侦听器并订阅它的事件.所以,让我们在我们这样做:HostingApplicationDiagnosticsWebHostWebHostBuilderStartup

public void ConfigureServices(IServiceCollection services)
{
    // …

    // register our observer
    services.AddSingleton<DiagnosticObserver>();
}

public void Configure(IApplicationBuilder app, IHostingEnvironment env,
    // we inject both the DiagnosticListener and our DiagnosticObserver here
    DiagnosticListener diagnosticListenerSource, DiagnosticObserver diagnosticObserver)
{
    // subscribe to the listener
    diagnosticListenerSource.Subscribe(diagnosticObserver);

    // …
}

这已足以让我们DiagnosticObserver跑步了.我们的观察员需要实施IObserver<KeyValuePair<string, object>>.当事件发生时,我们将获得一个键值对,其中键是事件的标识符,值是由传递的自定义对象HostingApplicationDiagnostics.

但是在我们实现观察者之前,我们应该看看HostingApplicationDiagnostics实际上提出了什么样的事件.

不幸的是,在请求结束时,即在诊断利斯特提出的事件只是被传递的结束时间戳,所以我们还需要听时引发该事件在开始阅读开始时间戳的要求.但这会将状态引入我们的观察者,这是我们想要避免的.此外,实际的事件名称常量前缀Deprecated可能是我们应该避免使用这些常量的指示符.

首选方法是使用与诊断观察者密切相关的活动.活动显然是跟踪应用程序中出现的活动的状态.它们在某些时候开始和停止,并且已经记录了它们自己运行的时间.因此,我们可以让我们的观察者监听活动的停止事件,以便在完成时收到通知:

public class DiagnosticObserver : IObserver<KeyValuePair<string, object>>
{
    private readonly ILogger<DiagnosticObserver> _logger;
    public DiagnosticObserver(ILogger<DiagnosticObserver> logger)
    {
        _logger = logger;
    }

    public void OnCompleted() { }
    public void OnError(Exception error) { }

    public void OnNext(KeyValuePair<string, object> value)
    {
        if (value.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop")
        {
            var httpContext = value.Value.GetType().GetProperty("HttpContext")?.GetValue(value.Value) as HttpContext;
            var activity = Activity.Current;

            _logger.LogWarning("Request ended for {RequestPath} in {Duration} ms",
                httpContext.Request.Path, activity.Duration.TotalMilliseconds);
        }
    }
}

不幸的是,没有没有缺点的解决方案......我发现这个解决方案对于并行请求是非常不准确的(例如,当打开一个也有并行请求的图像或脚本的页面时).这可能是因为我们使用静态Activity.Current来获取活动.然而,似乎没有办法只获得单个请求的活动,例如来自传递的键值对.

所以我回过头来再次尝试了我原来的想法,使用那些已弃用的事件.我理解它的方式是顺便说一句.他们刚被弃用是因为建议使用活动,而不是因为它们很快就会删除(当然我们正在处理实现细节和内部类,所以这些东西可能随时改变).为了避免并发问题,我们需要确保将状态存储在HTTP上下文(而不是类字段)中:

private const string StartTimestampKey = "DiagnosticObserver_StartTimestamp";

public void OnNext(KeyValuePair<string, object> value)
{
    if (value.Key == "Microsoft.AspNetCore.Hosting.BeginRequest")
    {
        var httpContext = (HttpContext)value.Value.GetType().GetProperty("httpContext").GetValue(value.Value);
        httpContext.Items[StartTimestampKey] = (long)value.Value.GetType().GetProperty("timestamp").GetValue(value.Value);
    }
    else if (value.Key == "Microsoft.AspNetCore.Hosting.EndRequest")
    {
        var httpContext = (HttpContext)value.Value.GetType().GetProperty("httpContext").GetValue(value.Value);
        var endTimestamp = (long)value.Value.GetType().GetProperty("timestamp").GetValue(value.Value);
        var startTimestamp = (long)httpContext.Items[StartTimestampKey];

        var duration = new TimeSpan((long)((endTimestamp - startTimestamp) * TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency));
        _logger.LogWarning("Request ended for {RequestPath} in {Duration} ms",
            httpContext.Request.Path, duration.TotalMilliseconds);
    }
}

运行此操作时,我们实际上可以获得准确的结果,并且我们还可以访问HttpContext,我们可以使用它来识别请求.当然,这里涉及的开销是非常明显的:反映访问属性值,必须存储信息HttpContext.Items,整个观察者的事情一般......这可能不是一个非常高效的方式来做到这一点.

关于诊断源和活动的更多内容:DiagnosticSource用户指南和活动用户指南.

记录

在上面的某处,我提到过HostingApplicationDiagnostics它还会将信息报告给日志记录设施.当然:这毕竟是我们在控制台中看到的.如果我们查看实现,我们可以看到这已经计算出适当的持续时间.由于这是结构化日志记录,我们可以使用它来获取该信息.

因此,让我们尝试编写一个自定义记录器,检查该确切的状态对象,看看我们能做些什么:

public class RequestDurationLogger : ILogger, ILoggerProvider
{
    public ILogger CreateLogger(string categoryName) => this;
    public void Dispose() { }
    public IDisposable BeginScope<TState>(TState state) => NullDisposable.Instance;
    public bool IsEnabled(LogLevel logLevel) => true;

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        if (state.GetType().FullName == "Microsoft.AspNetCore.Hosting.Internal.HostingRequestFinishedLog" &&
            state is IReadOnlyList<KeyValuePair<string, object>> values &&
            values.FirstOrDefault(kv => kv.Key == "ElapsedMilliseconds").Value is double milliseconds)
        {
            Console.WriteLine($"Request took {milliseconds} ms");
        }
    }

    private class NullDisposable : IDisposable
    {
        public static readonly NullDisposable Instance = new NullDisposable();
        public void Dispose() { }
    }
}

不幸的是(你现在可能喜欢这个词,对吧？),州级HostingRequestFinishedLog是内部的,所以我们不能直接使用它.所以我们必须使用反射来识别它.但是我们只需要它的名字,然后我们可以从只读列表中提取值.

现在我们需要做的就是将logger(provider)注册到web主机:

WebHost.CreateDefaultBuilder(args)
    .ConfigureLogging(logging =>
    {
        logging.AddProvider(new RequestDurationLogger());
    })
    .UseStartup<Startup>()
    .Build();

实际上,我们需要能够访问标准日志记录所具有的完全相同的信息.

但是,有两个问题:我们这里没有HttpContext,因此我们无法获得有关此持续时间实际属于哪个请求的信息.正如您所看到的HostingApplicationDiagnostics,此日志记录调用实际上仅在日志级别至少Information时才进行.

我们可以通过_httpContext使用反射读取私有字段来获取HttpContext,但是我们无法对日志级别做任何事情.当然,我们正在创建一个记录器以从一个特定的日志记录调用中获取信息这一事实是一个超级黑客,无论如何可能不是一个好主意.

结论

所以,这太可怕了.根本没有干净的方法从中检索这些信息HostingApplicationDiagnostics.我们还必须记住,诊断内容实际上只在启用时运行.而性能关键型应用程序可能会在某个时刻禁用它.无论如何,将这些信息用于诊断之外的任何事情都是一个坏主意,因为它一般来说太脆弱了.

那么什么是更好的解决方案？一个超出诊断环境的解决方案？一个早期运行的简单中间件 ; 就像你已经使用过一样.是的,这可能不如从外部请求处理管道遗漏一些路径那样准确,但它仍然是实际应用程序代码的准确度量.毕竟,如果我们想要测量框架性能,我们必须从外部测量它:作为客户端,发出请求(就像基准测试一样).

顺便说一下.这也是Stack Overflow自己的MiniProfiler的工作原理.你只是提前注册中间件,就是这样.