如何获得实际的请求执行时间 [英] How to get actual request execution time
问题描述
给出以下中间件:
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)值中捕获实际的请求执行时间?我想将此值存储在数据库中或在其他地方使用.
我认为这个问题确实很有趣，因此我对此进行了一些研究，以弄清楚WebHost如何实际测量和显示请求时间.最重要的是:获取此信息既没有好的，简单的方法，也没有很漂亮的方法，一切都感觉像是被黑客入侵了.但是，如果您仍然有兴趣，请继续.
启动应用程序时，WebHostBuilder会构造WebHost，进而创建HostingApplication.这基本上是负责响应传入请求的根组件.当请求进入时，它将是调用中间件管道的组件.
也是 组件，它将创建 DiagnosticListener .
诊断侦听器
DiagnosticListener是一件有趣的事情:它基本上是一个通用的事件接收器您可以发起事件.然后其他对象可以订阅它以侦听这些事件.因此，这听起来很符合我们的目的！
HostingApplicationDiagnostics使用的DiagnosticListener对象由WebHost传递，它实际上注册者WebHostBuilder作为单例，我们实际上可以从依赖项注入中解析侦听器并订阅其事件.因此，让我们在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传递的自定义对象.
但是在实现观察者之前，我们实际上应该查看什么样的事件在一开始就读取开始时间戳的请求.但这会将状态引入我们的观察者，这是我们在此要避免的事情.此外，实际的事件名称常量为带有Deprecated 前缀，这可能是我们应该避免使用它们的指示.
首选方法是使用活动与诊断观察者也密切相关.活动显然是一种状态，可以很好地跟踪应用程序中出现的活动.它们在某个时刻启动和停止，还已经记录了它们自己运行多长时间.因此，我们可以让观察者听一下stop事件，以便在活动完成时获得通知:
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中，这通常是整个观察者的事情……这可能不是执行此操作的一种非常有效的方法.
有关诊断源和活动的更多信息:看一下实现，我们可以看到这里已经计算出适当的持续时间.由于这是结构化的日志记录，因此我们可以使用它来获取该信息.
因此，让我们尝试编写一个自定义记录器，以检查 不幸的是(状态代码 现在我们要做的就是在Web主机上注册该记录器(提供者): 实际上，我们所需的就是能够访问与标准日志记录完全相同的信息. 但是，有两个问题:这里没有HttpContext，因此我们无法获得有关此持续时间实际上属于哪个请求的信息.正如您在 Given the following middleware: Because of the pipeline, it occurs before the end of pipeline and logs different times: How can I capture the actual request execution time from WebHost (405.1196ms in the example) value in this case? I want to store this value in database or use it elsewhere. I thought this question was really interesting, so I looked into this for a bit to figure out how the WebHost is actually measuring and displaying that request time. Bottom line is: There is neither a good nor an easy nor a pretty way to get this information, and everything feels like a hack. But follow along if you’re still interested. When the application is started, the It is also the component that will create Not that surprisingly, There are two things the diagnostics object uses to report diagnostics information: A logger, and a The The That’s already enough to get our But before we implement our observer, we should actually look at what kind of events Unfortunately, when the request ends, the event that is raised on the diagnostic lister just gets passed the end timestamp, so we would also need to listen to the event that is raised at the beginning of the request to read the start timestamp. But that would introduce state into our observer which is something we want to avoid here. In addition, the actual event name constants are prefixed with The preferred way is to use activities which are also closely related to the diagnostic observer. Activities are apparently states that track, well, activities as they appear in the application. They are started and stopped at some point, and also already record how long they run on their own. So we can just make our observer listen to the stop event for the activity to get notified when its done: Unfortunately there is just no solution without downsides… I found this solution to be very inaccurate for parallel requests (e.g. when opening a page that has also images or scripts which are requested in parallel). This is likely due to the fact that we are using a static So I went back and tried my original idea again, using those deprecated events. The way I understood it is btw. that they are just deprecated because using activities is recommended, not because they will be removed soon (of course we are working with implementation details and an internal class here, so these things could change at any time). To avoid problems with concurrency, we need to make sure we store the state inside of the HTTP context (instead of a class field): When running this, we do actually get accurate results and we also have access to the HttpContext which we can use to identify the request. Of course, the overhead that’s involved here is very apparent: Reflection to access property values, having to store information in Futher reading on diagnostic source and activities: DiagnosticSource Users Guid and Activity User Guide. Somewhere above I mentioned that the So let’s attempt to write a custom logger that checks for that exact state object and see what we can do: Unfortunately (you probably love this word by now, right?), the state class Now all we need to do is register that logger (provider) with the web host: And that’s actually all we need to be able to access the exact same information that the standard logging also has. However, there are two problems: We don’t have a HttpContext here, so we cannot get information about which request this duration actually belongs to. And as you can see in the We could get the HttpContext by reading the private field So, this is all terrible. There simply is no clean way to retrieve this information from the So what is the better solution? A solution that works outsid of a diagnostics context? A simple middleware that runs early; just like you have already used. Yes, this is likely not as accurate as it will leave out a few paths from the outer request handling pipeline but it will still be an accurate measurement for the actual application code. After all, if we wanted to measure framework performance, we would have to measure it from the outside anyway: as a client, making requests (just like the benchmarks work). And btw. this is also how Stack Overflow’s own MiniProfiler works. You just register the middleware early and that’s it. 这篇关于如何获得实际的请求执行时间的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！HostingRequestFinishedLog是内部的，所以您不能直接使用它)(您现在可能已经爱上了这个单词，对吧?).因此，我们必须使用反射来识别它.但是我们只需要它的名称，然后我们就可以从只读列表中提取值.WebHost.CreateDefaultBuilder(args)
.ConfigureLogging(logging =>
{
logging.AddProvider(new RequestDurationLogger());
})
.UseStartup<Startup>()
.Build();
HostingApplicationDiagnostics中所看到的那样，实际上仅在 MiniProfiler 的工作方式.您只需尽早注册中间件即可.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"
WebHostBuilder constructs the WebHost which in turn creates the HostingApplication. That’s basically the root component that is responsible to respond to incoming requests. It is the component that will invoke the middleware pipeline when a request comes in.HostingApplicationDiagnostics which allows to collect diagnostics about the request handling. At the beginning of the request, the HostingApplication will call HostingApplicationDiagnostics.BeginRequest, and at the end of the request, it will call HostingApplicationDiagnostics.RequestEnd.HostingApplicationDiagnostics is the thing that will measure the request duration and also log that message for the WebHost that you have been seeing. So this is the class that we have to inspect more closely to figure out how to get the information.DiagnosticListener.Diagnostic listener
DiagnosticListener is an interesting thing: It is basically a general event sink that you can just raise events on. And other objects can then subscribe to it to listen to these events. So this almost sounds perfect for our purpose!DiagnosticListener object that the HostingApplicationDiagnostics uses is passed on by the WebHost and it actually gets resolved from dependency injection. Since it is registered by the WebHostBuilder as a singleton, we can actually just resolve the listener from dependency injection and subscribe to its events. So let’s just do that in our 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 running. Our observer needs to implement IObserver<KeyValuePair<string, object>>. When an event occurs, we will get a key-value-pair where the key is an identifier for the event, and the value is a custom object that is passed by the HostingApplicationDiagnostics.HostingApplicationDiagnostics actually raises.Deprecated which might be an indicator that we should avoid using these.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 to get the activity. However there does not really seem to be a way to get just the activity for a single request, e.g. from the key value pair that was passed.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.Items, the whole observer thing in general… that’s probably not a very performant way to do this.Logging
HostingApplicationDiagnostics also reports the information to the logging facilities. Of course: This is what we are seeing in the console after all. And if we look at the implementation, we can see that this already calculates the proper duration here. And since this is structured logging, we could use this to grab that information.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 is internal, so we cannot use it directly. So we have to use reflection to identify it. But we just need its name, then we can extract the value from the read-only list.WebHost.CreateDefaultBuilder(args)
.ConfigureLogging(logging =>
{
logging.AddProvider(new RequestDurationLogger());
})
.UseStartup<Startup>()
.Build();
HostingApplicationDiagnostics, this logging call is actually only made when the log level is at least Information._httpContext using reflection but there is just nothing we can do about the log level. And of course, the fact that we are creating a logger to grab information from one specific logging call is a super hack and probably not a good idea anyway.Conclusion
HostingApplicationDiagnostics. And we also have to keep in mind that the diagnostics stuff actually only runs when it’s enabled. And performance critical applications will likely disable it at one point or another. In any way, using this information for anything outside of diagnostics would be a bad idea since it’s just too fragile in general.
