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

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 的消息的东西。你一直看到的。所以这是我们必须更仔细地检查以找出如何获取信息的类。

诊断对象用于报告诊断信息有两种方式:记录器和 DiagnosticListener .

诊断监听器
DiagnosticListener很有意思的一点:基本就是个一般event sink您可以在其上引发事件。然后其他对象可以订阅它来监听这些事件。所以这听起来非常适合我们的目的!
DiagnosticListener HostingApplicationDiagnostics 的对象用途由 WebHost 传递它实际上 gets resolved from dependency injection .既然是registered by the WebHostBuilder as a singleton ，我们实际上可以从依赖注入(inject)解析监听器并订阅它的事件。所以让我们在我们的 Startup 中这样做:

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 实际上提高。

不幸的是，当请求结束时，诊断列表中引发的事件刚刚通过 the end timestamp ，所以我们还需要监听引发的事件 at the beginning请求读取开始时间戳。但这会将状态引入我们的观察者，这是我们想要避免的。另外，实际的事件名称常量是prefixed with Deprecated 这可能是我们应该避免使用这些的指标。

首选方法是使用 activities这也与诊断观察者密切相关。事件显然是跟踪出现在应用程序中的事件的状态。它们在某个时刻开始和停止，并且已经记录了它们自己运行的时间。所以我们可以让我们的观察者监听事件的停止事件，以便在事件完成时得到通知:

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 Users Guid和 Activity User Guide .

日志记录

在上面的某个地方我提到了 HostingApplicationDiagnostics还将信息报告给日志记录设施。当然:这毕竟是我们在控制台中看到的。如果我们 look at the implementation ，我们可以看到这里已经计算了适当的持续时间。由于这是结构化日志，我们可以使用它来获取该信息。

因此，让我们尝试编写一个自定义记录器来检查 that exact state object看看我们能做什么:

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是内部的，所以我们不能直接使用它。所以我们必须使用反射来识别它。但是我们只需要它的名字，然后我们就可以从只读列表中提取值。

现在我们需要做的就是向 Web 主机注册该记录器(提供程序):

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

这实际上就是我们能够访问标准日志记录所具有的完全相同的信息所需要的全部内容。

但是，有两个问题:我们这里没有 HttpContext，因此我们无法获取有关此持续时间实际上属于哪个请求的信息。正如您在 HostingApplicationDiagnostics 中看到的那样，此日志记录调用实际上仅在 the log level is at least Information 时进行.

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

结论

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

那么更好的解决方案是什么？在诊断上下文之外工作的解决方案？一个早期运行的简单中间件；就像你已经用过一样。是的，这可能不像它会从外部请求处理管道中遗漏一些路径那样准确，但它仍然是实际应用程序代码的准确度量。毕竟，如果我们想衡量框架性能，无论如何我们都必须从外部衡量它:作为客户端，发出请求(就像基准测试一样)。

顺便说一句。这也是 Stack Overflow 自己的 MiniProfiler作品。你只是register the middleware early就是这样。