Skip to content
This repository has been archived by the owner on Dec 19, 2018. It is now read-only.

Higher accuracy in timings #543

Closed
wants to merge 1 commit into from
Closed

Higher accuracy in timings #543

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 20 additions & 11 deletions src/Microsoft.AspNet.Hosting/Internal/HostingApplication.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 });
}
}

Expand All @@ -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; }
}
}
}
14 changes: 7 additions & 7 deletions src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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));
Expand All @@ -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,
Expand Down