Add Time.monotonic to return monotonic clock #5108

ysbaddaden · 2017-10-12T08:52:49Z

Exposes Time.monotonic as a Time::Span with unspecified starting point, but guaranteed to be always increasing, and ready for time span computations, comparisons, ...

Also introduces a Time.measure(&block) sugar to measure how long a block takes to run —using the monotonic clock, obviously.

Relies on clock_gettime(CLOCK_REALTIME) on POSIX platforms, but rely on mach_absolute_time on macOS, which is more widely available and is supposed to have a higher precision.

Supersedes #5107 and #3827.

ysbaddaden · 2017-10-12T08:59:52Z

I hope this can be a common ground that's acceptable to everyone:

it merely exposes the monotonic clock, so it can be used for other purposes than measuring elapsed time —e.g. record the creation time of objects in memory then use it for sorting, detecting and deleting expired objects, all that independently from discontinous jumps to the computer clock;
it's independent and thus future proof to whether or not we compute/merge both monotonic + realtime clocks into Time.now (let's talk endlessly about that in another issue/pull request);
it proposes a little sugar for the common "measure elapsed time" feature.

ping @oprypin @asterite @RX14

RX14

Perhaps its time to seperate crystal/system/unix/time.cr into generic unix and darwin versions. I don't mind if that's another PR though.

Have you checked modules such as Benchmark to start using monotonic time?

RX14 · 2017-10-12T10:29:59Z

spec/std/time/time_spec.cr

+
+  it "measures elapsed time using monotonic clock" do
+    span = Time.measure { sleep 1.millisecond }
+    span.should be >= 1.millisecond


I would put an upper bound of 2-5ms on this.

I'm not sure to understand. Can you detail?

Just chack that span is 1.millisecond <= span <= 10.milliseconds. If we get a weird value like 1.second after a sleep 1.millisecond we should probably fail. I realise that on a heavilly loaded system this may break but I think that this is a worthwhile spec regardless.

Oh no no no. The test is currently in a much better state than this suggestion of a flaky test. Again you overestimate the accuracy of system timers.
At least on Windows I know that sleeping for 1 millisecond can skip the sleep entirely [1], and that the resolution at least on some old system that I used was about 12 ms.

[1]: https://msdn.microsoft.com/en-us/library/windows/desktop/ms686298(v=vs.85).aspx

If dwMilliseconds is less than the resolution of the system clock, the thread may sleep for less than the specified length of time

Ok, use 100ms then. If your 1ms sleep turns into a 100ms sleep then your system is broken and its pointless running specs on it regardless.

This isn't production code, this is the spec suite. If a test fails nothing breaks, unless we happen to be using such broken machines on CI.

Looking at the CI failures, I guess we can go for something like sleep 30; 20 <= span <= 100

straight-shoota · 2017-10-12T11:18:28Z

@RX14 Yes, the usage of measuring time with Time.now - start needs to be updated in several places in the stdlib.
This should at best be included as a second commit in this PR but could also be a different one. I wouldn't mind to take this.

straight-shoota · 2017-10-12T12:34:45Z

src/benchmark.cr

@@ -134,8 +134,6 @@ module Benchmark
  # Benchmark.realtime { "a" * 100_000 } # => 00:00:00.0005840
  # ```


Shouldn't this method be removed/deprecated if it's just an alias for Time.measure?

I would support either removing Time.measure or moving entire Benchmark somewhere else.

What does moving entire Benchmark somewhere else mean?

Removing Benchmark module but keeping its functionality somewhere.
My point is that Benchmark feels weird going into complicated stuff without the very basic benchmarking operation available in it.

Ah. Well but that's out of the scope of this PR ;)

Yes, either Benchmark.realtime or Time.measure should be dropped. Since Time.measure is always available and has a broader meaning (doesn't imply benchmarking), I would remove Benchmark.realtime but I don't have a strong opinion.

Removing Benchmark altogether is out-of-scope, indeed.

I'd say Time.measure is definitely better: This feature is not specificly benchmarking, just measuring time. Thus it's also better understandable than Benchmark.realtime.

The problem I see is that people looking at Benchmark module will be overwhelmed because there's not a single method returning a directly usable amount of time. In case of this removal, please add a comment about Time.measure to Benchmark.

straight-shoota · 2017-10-12T12:36:15Z

src/benchmark.cr

@@ -117,9 +117,9 @@ module Benchmark

  # Returns the time used to execute the given block.
  def measure(label = "") : BM::Tms
-    t0, r0 = Process.times, Time.now
+    t0, r0 = Process.times, Time.monotonic


Why not use Time.measure here?

tms0 = Process.times elapsed = Time.measure do yield end tms1 = Process.times BM::Tms.new(tms1.utime - tms0.utime, tms1.stime - tms0.stime, tms1.cutime - tms0.cutime, tms1.cstime - tms0.cstime, elapsed.total_seconds, label)

I would hold off on unnecessary changes like that, at least in this PR. They don't simplify anything but do cause errors, as you've pointed out elsewhere.

Errors only occur if it involves a return value from the block. Here this doesn't matter.

I think it should be worth advocating the more idiomatic Time.measure when possible.

This way it's obvious both measurements are related. It also avoids too much refactor for little purpose.

straight-shoota · 2017-10-12T12:40:40Z

src/benchmark/ips.cr

-            count += 1
+          elapsed = Time.measure do
+            target = Time.monotonic + @warmup_time
+            count = 0


count needs to be defined outside the block.

Pushed too early.

straight-shoota · 2017-10-12T12:42:16Z

src/compiler/crystal/progress_tracker.cr

-      start_time = Time.now
-      retval = yield
-      time_taken = Time.now - start_time
+      time_taken = Time.measure { retval = yield }


This shouldn't work because retval is not known outside the block. I guess you need to use Time.monotonic here. Might work with defining retval as uninitialized.

This might work:

retval = uninitialized typeof(yield) time_taken = measure do retval = yield end

Don't use uninitialized willy-nilly. retval = nil

retval = nil would add Nil to the return types of the method and then you'd have to use retval.not_nil!
So it's probably best to just use Time.monotonic without a block

straight-shoota · 2017-10-12T14:20:18Z

src/crystal/system/unix/time.cr

-      nanoseconds = LibC.mach_absolute_time.to_i64 * info.numer / info.denom
-      {nanoseconds / 1_000_000_000, nanoseconds.remainder(1_000_000_000).to_i32}
+      absolute_time = LibC.mach_absolute_time * mach_ticks_per_nanosecond
+      seconds = absolute_time / 1_000_000_000


NANOSECONDS_PER_SECOND ?

ysbaddaden · 2017-10-12T15:49:34Z

A spec is failing on CircleCI:

  1) Time measures elapsed time using monotonic clock
     Failure/Error: span.should be >= 1.millisecond

       Expected 00:00:00.000009349 to be >= 00:00:00.001000000

I thought truncating the absolute time to Int64 then multiplicating caused an overflow, so I tried a patch to use floats instead, but it still fails. I can't reproduce the issue in a Maveriks VM (freshly booted), neither with a UInt64 or Float64.

Can someone on macOS try this out?

oprypin · 2017-10-12T15:59:11Z

src/crystal/system/unix/time.cr

-      info = mach_timebase_info
-      nanoseconds = LibC.mach_absolute_time.to_i64 * info.numer / info.denom
-      {nanoseconds / 1_000_000_000, nanoseconds.remainder(1_000_000_000).to_i32}
+      absolute_time = LibC.mach_absolute_time * mach_ticks_per_nanosecond


Please revert this last change. It's really confusing because usually you'd divide by "ticks per nanosecond" but this is actually "nanoseconds per tick".

oprypin · 2017-10-12T16:01:10Z

@ysbaddaden Previously I quoted some Windows documentation

If dwMilliseconds is less than the resolution of the system clock, the thread may sleep for less than the specified length of time

Could be the same happening here, who knows. Just can't work with these tiny sleeps. I wouldn't expect anything less than 20 ms to be reliable.

RX14 · 2017-10-12T16:38:16Z

@oprypin sleep doesn't use system sleep, it uses libevent sleep which I assume doesn't rely on OS sleep. It replies on timing out waiting on events. I presumed it wouldn't be so inaccurate.

akzhan · 2017-10-12T17:31:53Z

MacOS

LLVM_CONFIG=/usr/local/bin/llvm-config-5.0 make clean
LLVM_CONFIG=/usr/local/bin/llvm-config-5.0 make crystal
➜  crystal git:(std-time-monotonic) ✗ bin/crystal spec/std/time/time_spec.cr
Using compiled compiler at `.build/crystal'
............................................................................................

Finished in 3.73 milliseconds
92 examples, 0 failures, 0 errors, 0 pending
➜  crystal git:(std-time-monotonic) ✗ bin/crystal spec/std/time/span_spec.cr
Using compiled compiler at `.build/crystal'
.........................

Finished in 239 microseconds
25 examples, 0 failures, 0 errors, 0 pending

Darwin Kernel Version 16.7.0

ysbaddaden · 2017-10-13T07:46:03Z

I'm debugging CircleCI ans will commit/force-push/reset some specific commits, that will eventually disappear.

ysbaddaden · 2017-10-13T09:26:27Z

The implementation is correct. The spec passes on CircleCI when called directly, but fails when running the whole std_spec suite. I guess @oprypin is right: the sleep may be too small and libevent resumes the fiber quickly for some reason.

ysbaddaden · 2017-10-13T09:32:28Z

Even with 100 millisecond, it fails.

RX14 · 2017-10-13T10:48:02Z

Lets just forget that whole spec...

Relies on `mach_absolute_time` on macOS, which is more widely available and is supposed to have a higher precision. Relies on `clock_gettime(CLOCK_RELATIME)` on other POSIX platforms. Exposes `Time.monotonic` as a `Time::Span` with unspecified starting point, but ready for time computations and comparisons. Also introduces a `Time.measure(&block)` sugar to measure how long a block takes to run —using the monotonic clock, obviously.

Mostly fixes spec, benchmark and some compiler timings.

ysbaddaden · 2017-10-13T11:46:41Z

spec/std/time/time_spec.cr

+    #       be resumed early. We thus merely test that the method returns a
+    #       positive time span.
+    elapsed = Time.measure { sleep 1.millisecond }
+    elapsed.should be >= 0.seconds


I simplified the spec, so we verify elapsed can be compared against a Time::Span and the value is always positive.

ysbaddaden · 2017-10-13T11:51:33Z

The one remaining question is what to do with the Benchmark.measure {} method that now strictly duplicates Time.measure {}.

I'd drop the former to favor to the new method, adding a note to the benchmark module pointing to Time.measure for measuring times, which seems to have the overall preference. But I'd like the opinion of other core members.

RX14 · 2017-10-13T12:51:14Z

Benchmarking to me has never been about measuring the time one thing takes once. That's not a benchmark, it's an unscientific measurement. Without the ability to do warmups and repeated runs, and without reporting results with deviations, it's largely pointless. I've never found a use for any other things in the Benchmark module part from ips. So I think this way is fine.

asterite · 2017-10-13T20:34:10Z

I'd really like @waj to review this before merge, if possible.

ysbaddaden requested a review from RX14 October 12, 2017 09:00

oprypin approved these changes Oct 12, 2017

View reviewed changes

RX14 reviewed Oct 12, 2017

View reviewed changes

straight-shoota requested changes Oct 12, 2017

View reviewed changes

ysbaddaden force-pushed the std-time-monotonic branch from 9dd8a4c to b6d4c28 Compare October 12, 2017 13:15

straight-shoota reviewed Oct 12, 2017

View reviewed changes

ysbaddaden force-pushed the std-time-monotonic branch from c159fee to 1652420 Compare October 12, 2017 14:22

oprypin reviewed Oct 12, 2017

View reviewed changes

ysbaddaden force-pushed the std-time-monotonic branch from 1652420 to 11174a6 Compare October 13, 2017 07:45

ysbaddaden force-pushed the std-time-monotonic branch 5 times, most recently from c837f8d to e29be65 Compare October 13, 2017 09:14

ysbaddaden force-pushed the std-time-monotonic branch from e29be65 to ccca95a Compare October 13, 2017 09:27

ysbaddaden added 2 commits October 13, 2017 13:42

Fix: always use monotonic clock to measure time

b5aabb9

Mostly fixes spec, benchmark and some compiler timings.

ysbaddaden force-pushed the std-time-monotonic branch from ccca95a to b5aabb9 Compare October 13, 2017 11:44

ysbaddaden commented Oct 13, 2017

View reviewed changes

RX14 approved these changes Oct 23, 2017

View reviewed changes

RX14 added this to the Next milestone Oct 23, 2017

RX14 added kind:feature topic:stdlib labels Oct 23, 2017

RX14 merged commit 007899a into crystal-lang:master Oct 23, 2017

ysbaddaden deleted the std-time-monotonic branch October 24, 2017 08:37

		@@ -134,8 +134,6 @@ module Benchmark
		# Benchmark.realtime { "a" * 100_000 } # => 00:00:00.0005840
		# ```

Add Time.monotonic to return monotonic clock #5108

Add Time.monotonic to return monotonic clock #5108

Conversation

ysbaddaden commented Oct 12, 2017 • edited Loading

ysbaddaden commented Oct 12, 2017

RX14 left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RX14 Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

straight-shoota commented Oct 12, 2017

straight-shoota Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

oprypin Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

oprypin Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

straight-shoota Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

straight-shoota Oct 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ysbaddaden commented Oct 12, 2017

Choose a reason for hiding this comment

oprypin commented Oct 12, 2017

RX14 commented Oct 12, 2017 • edited Loading

akzhan commented Oct 12, 2017 • edited Loading

ysbaddaden commented Oct 13, 2017

ysbaddaden commented Oct 13, 2017

ysbaddaden commented Oct 13, 2017

RX14 commented Oct 13, 2017

Choose a reason for hiding this comment

ysbaddaden commented Oct 13, 2017

RX14 commented Oct 13, 2017 • edited Loading

asterite commented Oct 13, 2017

ysbaddaden commented Oct 12, 2017 •

edited

Loading

RX14 left a comment •

edited

Loading

RX14 Oct 12, 2017 •

edited

Loading

straight-shoota Oct 12, 2017 •

edited

Loading

oprypin Oct 12, 2017 •

edited

Loading

oprypin Oct 12, 2017 •

edited

Loading

straight-shoota Oct 12, 2017 •

edited

Loading

straight-shoota Oct 12, 2017 •

edited

Loading

RX14 commented Oct 12, 2017 •

edited

Loading

akzhan commented Oct 12, 2017 •

edited

Loading

RX14 commented Oct 13, 2017 •

edited

Loading