Skip to content
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

Add Time.monotonic to return monotonic clock #5108

Merged
merged 2 commits into from
Oct 23, 2017
Merged
Show file tree
Hide file tree
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
13 changes: 13 additions & 0 deletions spec/std/time/time_spec.cr
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,19 @@ describe Time do
time.epoch_ms.should eq(milliseconds)
end

it "returns always increasing monotonic clock" do
clock = Time.monotonic
Time.monotonic.should be >= clock
end

it "measures elapsed time" do
# NOTE: On some systems, the sleep may not always wait for 1ms and the fiber
# 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
Copy link
Contributor Author

Choose a reason for hiding this comment

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

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

end

it "clones" do
time = Time.now
(time == time.clone).should be_true
Expand Down
8 changes: 3 additions & 5 deletions src/benchmark.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Member

Choose a reason for hiding this comment

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

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)

Copy link
Member

Choose a reason for hiding this comment

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

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.

Copy link
Member

Choose a reason for hiding this comment

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

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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

yield
t1, r1 = Process.times, Time.now
t1, r1 = Process.times, Time.monotonic
BM::Tms.new(t1.utime - t0.utime,
t1.stime - t0.stime,
t1.cutime - t0.cutime,
Expand All @@ -134,8 +134,6 @@ module Benchmark
# Benchmark.realtime { "a" * 100_000 } # => 00:00:00.0005840
# ```
Copy link
Member

@straight-shoota straight-shoota Oct 12, 2017

Choose a reason for hiding this comment

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

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

Copy link
Member

Choose a reason for hiding this comment

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

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

Copy link
Member

Choose a reason for hiding this comment

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

What does moving entire Benchmark somewhere else mean?

Copy link
Member

@oprypin oprypin Oct 12, 2017

Choose a reason for hiding this comment

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

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.

Copy link
Member

Choose a reason for hiding this comment

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

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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

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.

Copy link
Member

Choose a reason for hiding this comment

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

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.

Copy link
Member

@oprypin oprypin Oct 12, 2017

Choose a reason for hiding this comment

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

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.

def realtime : Time::Span
r0 = Time.now
yield
Time.now - r0
Time.measure { yield }
end
end
29 changes: 11 additions & 18 deletions src/benchmark/ips.cr
Original file line number Diff line number Diff line change
Expand Up @@ -60,18 +60,17 @@ module Benchmark
@items.each do |item|
GC.collect

before = Time.now
target = Time.now + @warmup_time
count = 0
elapsed = Time.measure do
target = Time.monotonic + @warmup_time

while Time.now < target
item.call
count += 1
while Time.monotonic < target
item.call
count += 1
end
end

after = Time.now

item.set_cycles(after - before, count)
item.set_cycles(elapsed, count)
end
end

Expand All @@ -80,20 +79,14 @@ module Benchmark
GC.collect

measurements = [] of Time::Span
target = Time.now + @calculation_time
target = Time.monotonic + @calculation_time

loop do
before = Time.now
item.call_for_100ms
after = Time.now

measurements << after - before

break if Time.now >= target
elapsed = Time.measure { item.call_for_100ms }
measurements << elapsed
break if Time.monotonic >= target
end

final_time = Time.now

ips = measurements.map { |m| item.cycles.to_f / m.total_seconds }
item.calculate_stats(ips)

Expand Down
13 changes: 7 additions & 6 deletions src/compiler/crystal/command.cr
Original file line number Diff line number Diff line change
Expand Up @@ -218,13 +218,14 @@ class Crystal::Command
time? = @time && !@progress_tracker.stats?
status, elapsed_time = @progress_tracker.stage("Execute") do
begin
start_time = Time.now
Process.run(output_filename, args: run_args, input: Process::Redirect::Inherit, output: Process::Redirect::Inherit, error: Process::Redirect::Inherit) do |process|
# Ignore the signal so we don't exit the running process
# (the running process can still handle this signal)
Signal::INT.ignore # do
elapsed = Time.measure do
Process.run(output_filename, args: run_args, input: Process::Redirect::Inherit, output: Process::Redirect::Inherit, error: Process::Redirect::Inherit) do |process|
# Ignore the signal so we don't exit the running process
# (the running process can still handle this signal)
Signal::INT.ignore # do
end
end
{$?, Time.now - start_time}
{$?, elapsed}
ensure
File.delete(output_filename) rescue nil

Expand Down
6 changes: 3 additions & 3 deletions src/compiler/crystal/macros/macros.cr
Original file line number Diff line number Diff line change
Expand Up @@ -104,7 +104,7 @@ class Crystal::Program
end

def macro_compile(filename)
time = Time.now
time = Time.monotonic

source = File.read(filename)

Expand All @@ -127,7 +127,7 @@ class Crystal::Program
File.utime(now, now, program_dir)

if can_reuse_previous_compilation?(filename, executable_path, recorded_requires_path, requires_path)
elapsed_time = Time.now - time
elapsed_time = Time.monotonic - time
return CompiledMacroRun.new(executable_path, elapsed_time, true)
end

Expand Down Expand Up @@ -166,7 +166,7 @@ class Crystal::Program
requires_with_timestamps.to_json(file)
end

elapsed_time = Time.now - time
elapsed_time = Time.monotonic - time
CompiledMacroRun.new(executable_path, elapsed_time, false)
end

Expand Down
4 changes: 2 additions & 2 deletions src/compiler/crystal/progress_tracker.cr
Original file line number Diff line number Diff line change
Expand Up @@ -18,9 +18,9 @@ module Crystal
print_stats
print_progress

start_time = Time.now
time_start = Time.monotonic
retval = yield
time_taken = Time.now - start_time
time_taken = Time.monotonic - time_start

print_stats(time_taken)
print_progress
Expand Down
7 changes: 4 additions & 3 deletions src/crystal/main.cr
Original file line number Diff line number Diff line change
Expand Up @@ -32,9 +32,10 @@ module Crystal
# ```
# fun main(argc : Int32, argv : UInt8**) : Int32
# Crystal.main do
# time = Time.now
# Crystal.main_user_code(argc, argv)
# puts "Time to execute program: #{Time.now - time}"
# elapsed = Time.measure do
# Crystal.main_user_code(argc, argv)
# end
# puts "Time to execute program: #{elapsed}"
# end
# end
# ```
Expand Down
35 changes: 35 additions & 0 deletions src/crystal/system/unix/time.cr
Original file line number Diff line number Diff line change
@@ -1,6 +1,15 @@
require "c/sys/time"
require "c/time"

{% if flag?(:darwin) %}
# Darwin supports clock_gettime starting from macOS Sierra, but we can't
# use it because it would prevent running binaries built on macOS Sierra
# to run on older macOS releases.
#
# Furthermore, mach_absolute_time is reported to have a higher precision.
require "c/mach/mach_time"
{% end %}

module Crystal::System::Time
UnixEpochInSeconds = 62135596800_i64

Expand Down Expand Up @@ -37,4 +46,30 @@ module Crystal::System::Time
{timeval.tv_sec.to_i64 + UnixEpochInSeconds, timeval.tv_usec.to_i * 1_000}
{% end %}
end

def self.monotonic
{% if flag?(:darwin) %}
info = mach_timebase_info
total_nanoseconds = LibC.mach_absolute_time * info.numer / info.denom
seconds = total_nanoseconds / 1_000_000_000
nanoseconds = total_nanoseconds.remainder(1_000_000_000)
{seconds.to_i64, nanoseconds.to_i32}
{% else %}
if LibC.clock_gettime(LibC::CLOCK_MONOTONIC, out tp) == 1
raise Errno.new("clock_gettime(CLOCK_MONOTONIC)")
end
{tp.tv_sec.to_i64, tp.tv_nsec.to_i32}
{% end %}
end

{% if flag?(:darwin) %}
@@mach_timebase_info : LibC::MachTimebaseInfo?

private def self.mach_timebase_info
@@mach_timebase_info ||= begin
LibC.mach_timebase_info(out info)
info
end
end
{% end %}
end
4 changes: 1 addition & 3 deletions src/http/server/handlers/log_handler.cr
Original file line number Diff line number Diff line change
Expand Up @@ -8,9 +8,7 @@ class HTTP::LogHandler
end

def call(context)
time = Time.now
call_next(context)
elapsed = Time.now - time
elapsed = Time.measure { call_next(context) }
elapsed_text = elapsed_text(elapsed)

@io.puts "#{context.request.method} #{context.request.resource} - #{context.response.status_code} (#{elapsed_text})"
Expand Down
9 changes: 9 additions & 0 deletions src/lib_c/x86_64-macosx-darwin/c/mach/mach_time.cr
Original file line number Diff line number Diff line change
@@ -0,0 +1,9 @@
lib LibC
struct MachTimebaseInfo
numer : UInt32
denom : UInt32
end

fun mach_timebase_info(info : MachTimebaseInfo*) : LibC::Int
fun mach_absolute_time : UInt64
end
4 changes: 2 additions & 2 deletions src/spec/dsl.cr
Original file line number Diff line number Diff line change
Expand Up @@ -166,9 +166,9 @@ module Spec

# :nodoc:
def self.run
start_time = Time.now
start_time = Time.monotonic
at_exit do
elapsed_time = Time.now - start_time
elapsed_time = Time.monotonic - start_time
Spec::RootContext.print_results(elapsed_time)
exit 1 unless Spec::RootContext.succeeded
end
Expand Down
8 changes: 4 additions & 4 deletions src/spec/methods.cr
Original file line number Diff line number Diff line change
Expand Up @@ -12,16 +12,16 @@ module Spec::Methods

Spec.formatters.each(&.before_example(description))

start = Time.now
start = Time.monotonic
begin
Spec.run_before_each_hooks
block.call
Spec::RootContext.report(:success, description, file, line, Time.now - start)
Spec::RootContext.report(:success, description, file, line, Time.monotonic - start)
rescue ex : Spec::AssertionFailed
Spec::RootContext.report(:fail, description, file, line, Time.now - start, ex)
Spec::RootContext.report(:fail, description, file, line, Time.monotonic - start, ex)
Spec.abort! if Spec.fail_fast?
rescue ex
Spec::RootContext.report(:error, description, file, line, Time.now - start, ex)
Spec::RootContext.report(:error, description, file, line, Time.monotonic - start, ex)
Spec.abort! if Spec.fail_fast?
ensure
Spec.run_after_each_hooks
Expand Down
20 changes: 20 additions & 0 deletions src/time.cr
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,26 @@ struct Time
@nanoseconds : Int32
@kind : Kind

# Returns a clock from an unspecified starting point, but strictly linearly
# increasing. This clock should be independent from discontinuous jumps in the
# system time, such as leap seconds, time zone adjustments or manual changes
# to the computer's time.
#
# For example, the monotonic clock must always be used to measure an elapsed
# time.
def self.monotonic : Time::Span
seconds, nanoseconds = Crystal::System::Time.monotonic
Time::Span.new(seconds: seconds, nanoseconds: nanoseconds)
end

# Measures how long the block took to run. Relies on `monotonic` to not be
# affected by time fluctuations.
def self.measure : Time::Span
start = monotonic
yield
monotonic - start
end

def self.new
seconds, nanoseconds, offset = Time.compute_seconds_nanoseconds_and_offset
new(seconds: seconds + offset, nanoseconds: nanoseconds, kind: Kind::Local)
Expand Down