huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Higher accuracy in timings

This commit is contained in:
Ben Adams 2016-01-01 20:14:01 +00:00 committed by John Luo
parent d422201e01
commit fa72fdeaed
2 changed files with 27 additions and 18 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

31
src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs
View File

@ -33,41 +33,50 @@ namespace Microsoft.AspNet.Hosting.Internal
public Context CreateContext(IFeatureCollection contextFeatures) public Context CreateContext(IFeatureCollection contextFeatures)
{ {
var httpContext = _httpContextFactory.Create(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); var scope = _logger.RequestScope(httpContext);
_logger.RequestStarting(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 return new Context
{ {
HttpContext = httpContext, HttpContext = httpContext,
Scope = scope, Scope = scope,
StartTick = startTick, StartTimestamp = startTimestamp,
}; };
} }
public void DisposeContext(Context context, Exception exception) public void DisposeContext(Context context, Exception exception)
{ {
var httpContext = context.HttpContext; var httpContext = context.HttpContext;
var currentTick = Environment.TickCount;
_logger.RequestFinished(httpContext, context.StartTick, currentTick);
if (exception == null) 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 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 @@ namespace Microsoft.AspNet.Hosting.Internal
{ {
public HttpContext HttpContext { get; set; } public HttpContext HttpContext { get; set; }
public IDisposable Scope { get; set; } public IDisposable Scope { get; set; }
public int StartTick { get; set; } public long StartTimestamp { get; set; }
} }
} }
} }

14
src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs
View File

@ -2,6 +2,7 @@
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System; using System;
using System.Diagnostics;
using System.Collections.Generic; using System.Collections.Generic;
using Microsoft.AspNet.Http; using Microsoft.AspNet.Http;
using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging;
@ -10,8 +11,8 @@ namespace Microsoft.AspNet.Hosting.Internal
{ {
internal static class HostingLoggerExtensions 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) public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
{ {
return logger.BeginScopeImpl(new HostingLogScope(httpContext)); return logger.BeginScopeImpl(new HostingLogScope(httpContext));
@ -30,13 +31,12 @@ namespace Microsoft.AspNet.Hosting.Internal
} }
} }
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 ? var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
(int.MaxValue - startTimeInTicks) + (currentTick - int.MinValue) :
currentTick - startTimeInTicks));
logger.Log( logger.Log(
logLevel: LogLevel.Information, logLevel: LogLevel.Information,