Higher accuracy in timings #543
Conversation
|
Before with
After with
|
|
Benchmark: https://gist.github.com/benaadams/988b223a2433dcf773fc
BenchmarkDotNet-Dev=v0.8.0.0+
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4720HQ CPU @ 2.60GHz, ProcessorCount=8
HostCLR=MS.NET 4.0.30319.42000, Arch=64-bit [RyuJIT]
Type=Measurements Mode=Throughput Platform=X64 Jit=RyuJit .NET=HostFramework toolchain=Classic Runtime=Clr Warmup=5 Target=10
Will reduce the cost when not logging times |
|
Now best of both worlds? |
As per aspnet/Hosting#543 Resolves aspnet#3849
|
Can the logger be enabled after the app has started? |
|
@DamianEdwards suggested it can at a talk |
benaadams
force-pushed
the
moar-accurate-timings
branch
from
8fcf38b to
22ca4a6
Compare
|
@pranavkm pointed out in aspnet/Mvc#3850 (diff) that you still get the right results if it wraps without needing to do the additions and subtractions, so taken them out. |
As per aspnet/Hosting#543 Resolves aspnet#3849
As per aspnet/Hosting#543 Resolves aspnet#3849
|
Isn't |
|
While It would mean you'd get the same effect as with |
|
It would likely be 4ms resolution on linux dotnet/coreclr#2293 |
|
Also on OSX at sure its even precise either as it might be also rounded to the millisecond https://github.com/dotnet/coreclr/issues/1300 |
You can actually use BenchmarkDotNet to give you this information, just write a benchmark like so for each method ( [Benchmark]
public long StopwatchGranularity()
{
// Keep calling Stopwatch.GetTimestamp() till we get a different/new value
long current, lastValue = Stopwatch.GetTimestamp();
do
{
current = Stopwatch.GetTimestamp();
} while (current == lastValue);
lastValue = current;
return current;
}And this article is also a pretty good read, http://shipilev.net/blog/2014/nanotrusting-nanotime/ |
As per aspnet/Hosting#543 Resolves #3849
|
|
||
| if (exception == null) | ||
| { | ||
| if (_diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest")) | ||
| { | ||
| _diagnosticSource.Write("Microsoft.AspNet.Hosting.EndRequest", new { httpContext = httpContext, tickCount = currentTick }); | ||
| _diagnosticSource.Write("Microsoft.AspNet.Hosting.EndRequest", new { httpContext = httpContext, tickCount = currentTimestamp }); |
There was a problem hiding this comment.
Should this be a TimeSpan? For starters tickCount is a bit of a misnomer with this change and doesn't convey the unit of measurement.
Also, changing this from int -> long \ TimeSpan, this would be a breaking change I know @avanderhoorn uses it in glimpse. Are there other folks we'd need to notify about this change?
There was a problem hiding this comment.
A time stamp isn't a TimeSpan. It's closer to a DateTime.
Rename the parameter.
There was a problem hiding this comment.
Huh. I thought it was subtracting the values. DateTimeOffset in that case?
There was a problem hiding this comment.
On a tangent, why wouldn't the listener time this? Wouldn't they need to pair the start-stop events to make sense of this?
There was a problem hiding this comment.
Renamed to timestamp; also enabled the checking if either the diagnostics is enabled or the logging (rather than just logging)
|
@avanderhoorn, what do you think? |
|
+1 Looks good to me. |
benaadams
force-pushed
the
moar-accurate-timings
branch
from
bd7532a to
076b57a
Compare
|
@JunTaoLuo can you merge this? |
|
Merged to dev in fa72fde |
Use Stopwatch.GetTimestamp for sub millisecond timings
Resolves #544