Fixes #18. Store longs instead of Stopwatch instance.

[davidpeden3]

Builds on https://github.com/nblumhardt/serilog-timings/pull/19

[nblumhardt]

This looks like the way to go 👍

I think since the logic is a bit sensitive in places, we should include some tests to make sure:

• The returned timespan is correct (e.g. use a Thread.Sleep(1000) and then check that Elapsed is between 990 and 1010 ms)
• That completing the operation stops the timer (and multiple completions don't extend it)
• Whatever semantics we need to enforce for cancellation (I am not sure about this one, what are your thoughts?)

Thanks again for the PR, I think it's a great step forward!

[nblumhardt]

Thanks for the updates.

I'm not getting the same resolution out of this that Stopwatch exhibits on its own:

> var start = Stopwatch.GetTimestamp();
> TimeSpan.FromSeconds((double)(Stopwatch.GetTimestamp() - start) / Stopwatch.Frequency)
[00:00:05.4230000]
> TimeSpan.FromSeconds((double)(Stopwatch.GetTimestamp() - start) / Stopwatch.Frequency)
[00:00:15.1470000]
> TimeSpan.FromSeconds((double)(Stopwatch.GetTimestamp() - start) / Stopwatch.Frequency)
[00:00:20.6790000]
> var sw = Stopwatch.StartNew();
> sw.Elapsed
[00:00:03.2453099]
> sw.Elapsed
[00:00:06.0213253]
> sw.Elapsed
[00:00:06.8832752]

Any ideas?

[davidpeden3]

It turns out that TimeSpan.FromSeconds kills the precision.

https://msdn.microsoft.com/en-us/library/system.timespan.fromseconds(v=vs.110).aspx

I've changed the implementation though I'm not sure how valid it is. Presumably the .NET Framework would do something along these lines if this were legit. Maybe this suggests that leveraging TimeSpan.GetTimestamp is not the right approach.

Let me know what you think.

[nblumhardt]

Thanks for the investigation and reply. Might need to dig into the source for Stopwatch.cs to see how it's done in the BCL, if the 'ticks' option doesn't work.

The update looks promising; instead of using Lazy could we just add an explicit get block for the Elapsed property?

[davidpeden3]

I made it a Lazy because it should only be calculated once. Is there a reason why you don't like the Lazy?

[nblumhardt]

Yah, Lazy requires allocating a the Func closure on the heap 👍. For instrumentation, minimizing heap allocs is worthwhile, since the timing might (for example) be run in a loop (getting rid of the Stopwatch allocation is the reason for #18).

We do, unfortunately, cause an Operation and a params object[] allocation as things stand; getting rid of those when the logging level is turned down might have been possible before we introduced the Elapsed property (it requires even "silent" operations to carry some operation-specific state), but since abandonment usually results in an error or warning, it's unlikely that optimization would have made any real-world difference.

[nblumhardt]

Hi David; I think this one is a bit stale and may take some effort to pick back up. I'll close it since a long time has now Elapsed :-p but let me know if you think we should move it forward at some point. Cheers!