From 076b57ae561a01cb6b1ced8ee80d1ea8cc33a21e Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Fri, 1 Jan 2016 20:14:01 +0000 Subject: [PATCH] Higher accuracy in timings --- .../Internal/HostingApplication.cs | 31 ++++++++++++------- .../Internal/HostingLoggerExtensions.cs | 14 ++++----- 2 files changed, 27 insertions(+), 18 deletions(-) diff --git a/src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs b/src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs index 5ed24535..7b77757e 100644 --- a/src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs +++ b/src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs @@ -33,41 +33,50 @@ public HostingApplication( public Context CreateContext(IFeatureCollection contextFeatures) { var httpContext = _httpContextFactory.Create(contextFeatures); - var startTick = Environment.TickCount; + var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest"); + var startTimestamp = (diagnoticsEnabled || _logger.IsEnabled(LogLevel.Information)) ? Stopwatch.GetTimestamp() : 0; var scope = _logger.RequestScope(httpContext); _logger.RequestStarting(httpContext); - if (_diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest")) + if (diagnoticsEnabled) { - _diagnosticSource.Write("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext, tickCount = startTick }); + _diagnosticSource.Write("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext, timestamp = startTimestamp }); } return new Context { HttpContext = httpContext, Scope = scope, - StartTick = startTick, + StartTimestamp = startTimestamp, }; } public void DisposeContext(Context context, Exception exception) { var httpContext = context.HttpContext; - var currentTick = Environment.TickCount; - _logger.RequestFinished(httpContext, context.StartTick, currentTick); if (exception == null) { - if (_diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest")) + var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest"); + var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0; + + _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp); + + if (diagnoticsEnabled) { - _diagnosticSource.Write("Microsoft.AspNet.Hosting.EndRequest", new { httpContext = httpContext, tickCount = currentTick }); + _diagnosticSource.Write("Microsoft.AspNet.Hosting.EndRequest", new { httpContext = httpContext, timestamp = currentTimestamp }); } } else { - if (_diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException")) + var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"); + var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0; + + _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp); + + if (diagnoticsEnabled) { - _diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, tickCount = currentTick, exception = exception }); + _diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, timestamp = currentTimestamp, exception = exception }); } } @@ -85,7 +94,7 @@ public struct Context { public HttpContext HttpContext { get; set; } public IDisposable Scope { get; set; } - public int StartTick { get; set; } + public long StartTimestamp { get; set; } } } } diff --git a/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs b/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs index 4f149d5b..0fdf1228 100644 --- a/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs +++ b/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Diagnostics; using System.Collections.Generic; using Microsoft.AspNet.Http; using Microsoft.Extensions.Logging; @@ -10,8 +11,8 @@ namespace Microsoft.AspNet.Hosting.Internal { internal static class HostingLoggerExtensions { - private const long TicksPerMillisecond = 10000; - + private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; + public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext) { return logger.BeginScopeImpl(new HostingLogScope(httpContext)); @@ -30,13 +31,12 @@ public static void RequestStarting(this ILogger logger, HttpContext httpContext) } } - public static void RequestFinished(this ILogger logger, HttpContext httpContext, int startTimeInTicks, int currentTick) + public static void RequestFinished(this ILogger logger, HttpContext httpContext, long startTimestamp, long currentTimestamp) { - if (logger.IsEnabled(LogLevel.Information)) + // Don't log if Information logging wasn't enabled at start or end of request as time will be wildly wrong. + if (startTimestamp != 0) { - var elapsed = new TimeSpan(TicksPerMillisecond * (currentTick < startTimeInTicks ? - (int.MaxValue - startTimeInTicks) + (currentTick - int.MinValue) : - currentTick - startTimeInTicks)); + var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); logger.Log( logLevel: LogLevel.Information,