Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

Sign up
Appearance settings

use Stopwatch for ElapsedMilliseconds #347

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
SimonCropp wants to merge 1 commit into dev from use-Stopwatch-for-ElapsedMilliseconds
Closed
Changes from all commits
Commits
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
12 changes: 3 additions & 9 deletions src/Serilog.AspNetCore/AspNetCore/RequestLoggingMiddleware.cs
View file Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,20 +53,19 @@ public async Task Invoke(HttpContext httpContext)
{
if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));

var start = Stopwatch.GetTimestamp();
var stopwatch = Stopwatch.StartNew();
Copy link
Member

@bartelink bartelink Sep 25, 2023
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While this is less cryptic for people scanning (and I also agree that the math is v error prone wrt overflow and/or getting int64 vs double conversions wrong), this line does allocate so I went the other way in my helpers in https://github.com/jet/propulsion/blob/master/src/Propulsion/Internal.fs#L9-L18
Having said that, I also do have lots of places where I actually want/need it to be in ticks so I can add lots together and then render variously as seconds, or ms.
I'd also note that the jitter and the compiler also have plenty special casing to make the math and/or inlining be more efficient than you'd expect for the code as it was
Also .net 7 adds a System.Diagnostics.Stopwatch.GetElapsedTime() so maybe that can be used?

Copy link
Member

@nblumhardt nblumhardt Sep 27, 2023
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 the shift to GetTimestamp() was to avoid a wasted allocation here; using GetElapsedTime() would be the best-of-both-worlds solution


var collector = _diagnosticContext.BeginCollection();
try
{
await _next(httpContext);
var elapsedMs = GetElapsedMilliseconds(start, Stopwatch.GetTimestamp());
var statusCode = httpContext.Response.StatusCode;
LogCompletion(httpContext, collector, statusCode, elapsedMs, null);
LogCompletion(httpContext, collector, statusCode, stopwatch.ElapsedMilliseconds, null);
}
catch (Exception ex)
// Never caught, because `LogCompletion()` returns false. This ensures e.g. the developer exception page is still
// shown, although it does also mean we see a duplicate "unhandled exception" event from ASP.NET Core.
when (LogCompletion(httpContext, collector, 500, GetElapsedMilliseconds(start, Stopwatch.GetTimestamp()), ex))
when (LogCompletion(httpContext, collector, 500, stopwatch.ElapsedMilliseconds, ex))
{
}
finally
Expand Down Expand Up @@ -97,11 +96,6 @@ bool LogCompletion(HttpContext httpContext, DiagnosticContextCollector collector
return false;
}

static double GetElapsedMilliseconds(long start, long stop)
{
return (stop - start) * 1000 / (double)Stopwatch.Frequency;
}

static string GetPath(HttpContext httpContext, bool includeQueryInRequestPath)
{
/*
Expand Down

AltStyle によって変換されたページ (->オリジナル) /