我觉得这个问题真的很有趣，所以我研究了一下，以了解 WebHost 是如何实际测量和显示请求时间的。底线是：获取这些信息既没有好方法，也没有简单的方法，也没有漂亮的方法，而且一切都感觉像是一个黑客。但如果您仍然感兴趣，请继续关注。
当应用程序启动时，WebHostBuilder 会构造 WebHost，而WebHost 又会创建HostingApplication。这基本上是负责响应传入请求的根组件。它是在请求进来时调用中间件管道的组件。
也是组件将创建HostingApplicationDiagnostics，它允许收集有关请求处理的诊断信息。在请求开始时，HostingApplication会调用HostingApplicationDiagnostics.BeginRequest，在请求结束时会调用HostingApplicationDiagnostics.RequestEnd。
这并不奇怪，HostingApplicationDiagnostics 将测量请求持续时间并记录您所看到的WebHost 的消息。所以这是我们必须更仔细检查的类，以确定如何获取信息。
诊断对象使用两个东西来报告诊断信息：一个记录器和一个DiagnosticListener。
诊断监听器
DiagnosticListener 是一个有趣的东西：它基本上是一个通用的event sink，你可以在上面引发事件。然后其他对象可以订阅它来监听这些事件。所以这对我们的目的来说几乎是完美的！
HostingApplicationDiagnostics 使用的DiagnosticListener 对象由WebHost 传递，它实际上是gets resolved from dependency injection。因为它是registered by the WebHostBuilder as a singleton，我们实际上可以从依赖注入中解析监听器并订阅它的事件。所以让我们在我们的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>>。当事件发生时，我们会得到一个key-value-pair，其中key是事件的标识符，value是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 是内部的，所以我们不能直接使用它。所以我们必须使用反射来识别它。但是我们只需要它的名字，然后我们就可以从只读列表中提取值。
现在我们需要做的就是向网络主机注册该记录器（提供者）：
WebHost.CreateDefaultBuilder(args)
.ConfigureLogging(logging =>
{
logging.AddProvider(new RequestDurationLogger());
})
.UseStartup<Startup>()
.Build();
这实际上就是我们需要能够访问与标准日志记录完全相同的信息的全部内容。
但是，有两个问题：我们这里没有 HttpContext，因此我们无法获取有关此持续时间实际属于哪个请求的信息。正如你在HostingApplicationDiagnostics 中看到的，这个日志调用实际上只在the log level is at least Information 时进行。
我们可以通过使用反射读取私有字段_httpContext 来获取 HttpContext，但是对于日志级别我们无能为力。当然，我们正在创建一个记录器来从一个特定的日志调用中获取信息这一事实是一个超级黑客，无论如何可能不是一个好主意。
结论
所以，这一切都很糟糕。根本没有干净的方法可以从HostingApplicationDiagnostics 检索此信息。而且我们还必须记住，诊断程序实际上只在启用时运行。性能关键应用程序可能会在某一时刻禁用它。无论如何，将这些信息用于诊断之外的任何事情都是一个坏主意，因为它一般来说太脆弱了。
那么更好的解决方案是什么？在诊断上下文之外工作的解决方案？ 一个早期运行的简单中间件;就像你已经用过一样。是的，这可能不准确，因为它会从外部请求处理管道中省略一些路径，但它仍然是对实际应用程序代码的准确测量。毕竟，如果我们想衡量框架的性能，无论如何我们都必须从外部衡量它：作为客户端，发出请求（就像基准测试一样）。
顺便说一句。这也是 Stack Overflow 自己的 MiniProfiler 的工作原理。你只需 register the middleware early 就可以了。