Skip to content

Carry nanoseconds from the wall clock into Time.now (#689) - #702

Merged
tannevaled merged 1 commit into
mainfrom
wt43/timenow-689
Sep 26, 2026
Merged

tannevaled merged 1 commit into
mainfrom
wt43/timenow-689

Conversation

@tannevaled

@tannevaled tannevaled commented Sep 26, 2026 •

Copy link
Copy Markdown
Contributor

Fixes #689.

The code path, traced rather than inferred

Time.now is registered in internal/vm/time.go (registerTime, sm("now", …))
and goes:

Time.now  →  (*VM).timeNow          internal/vm/time.go
          →  (*VM).nowInstant()     internal/vm/timecop.go
          →  vm.clock.Current()     go-ruby-timecop Clock (unmocked → its Now seam)
          →  the seam installed in NewWithStderr:
             timecop.NewWith(func() time.Time { return time.Unix(nowUnix(), 0).UTC() })
          →  var nowUnix = func() int64 { return time.Now().Unix() }

The truncation was in the type of the seam, not in Time.now's body. nowUnix
was declared func() int64, and the wiring then had to invent a nanosecond —
time.Unix(nowUnix(), 0). So the whole-second answer was a property of the clock,
not of its callers, and the clock has four callers: Time.now, Time.new with no
arguments, Date.today and DateTime.now (the last two through
withDeterministicClock, which already passed t.Nanosecond() on to the Date
library — it was receiving a zero).

That matters for how the issue reads the defect. The issue's localisation
("only Time.now's own construction drops the fraction") is right about where to
look and understates the blast radius by one step: DateTime.now.sec_fraction was
0 too, and Timecop.freeze(t) had a truncation of its own (below). Nothing was
wrong in Time's representation, exactly as the issue says — Time.at proving the
plumbing is what made this small.

timecop's Clock does not truncate: Current() returns the seam's instant, and
its freeze/travel/scale frames do time.Time arithmetic. So one seam change fixes
all four constructors.

What changed

  • internal/vm/time.go — the seam is now nowWall func() time.Time, returning a
    whole instant, which is what MRI's time_s_now → rb_time_timespec_now →
    clock_gettime(CLOCK_REALTIME) keeps in tv_nsec.
  • internal/vm/vm.go — the clock is wired to nowWall().UTC(); no nanosecond is
    invented any more.
  • internal/vm/timecop.go — timecopInstant resolved a Time argument through
    time.Unix(v.Unix(), 0), so Timecop.freeze(Time.at(x.25)) silently moved the
    clock back to the start of that second. It now takes the whole instant.
  • internal/vm/time.go — Time#- between two Times went through
    time.Time.Sub, whose time.Duration is nanosecond-granular, dropping the
    sub-nanosecond remainder a Time keeps in frac: (t + 0.000001) - t read
    9.99e-07 where MRI 4.0.5 reads 1.0e-06. It is now the exact rational
    difference converted to Float once, sharing one exactSeconds() helper with
    shiftByRat so the two cannot drift apart.

No change was needed anywhere in Time's accessors, rendering or arithmetic, and
builtins.go is untouched.

Measured against MRI 4.0.5

A 70-property probe (Time.now fields, Time.new, the in: keyword,
Process.clock_gettime per clock id, Time.at per argument type, Time#+/#-,
round/floor/ceil, File::Stat times, sleep granularity, Date/DateTime)
run under MRI 4.0.5 and under rbgo before and after. Every row that moved, moved to
MRI's answer:

MRI 4.0.5 rbgo before rbgo after
Time.now.usec non-zero, 20 samples 20 0 20
Time.now.nsec non-zero, 20 samples 20 0 20
Time.now deltas > 0, 200 pairs 8 0 48
elapsed over a busy loop > 0 true false true
Time.now.subsec.class Rational Integer Rational
Time.new.usec non-zero, 20 samples 20 0 20
Time.now(in: "+02:00").usec non-zero 20 0 20
Time.now.strftime("%6N") != "000000" 20 0 20
sleep 0.05 then Time.now - t0 > 0.04 true false true
DateTime.now.sec_fraction non-zero 20 0 20
(t + 0.000001) - t 1.0e-06 9.99e-07 1.0e-06

Time.now.subsec.class is worth a note: Integer was not a second defect —
MRI returns Integer 0 for a whole-second instant too. It was the zero showing
through.

The tests, and why they cannot flake

internal/vm/time_now_clock_internal_test.go. Time is the one subject where a test
must not assert a literal, so no instant is compared to a constant. Two legs:

  • pinned — nowWall is replaced by a fixed nanosecond-bearing instant and the
    value Ruby reads back is asserted exactly (nsec, usec, subsec, %N, %6N,
    Time.new, both in: paths, DateTime.now.sec_fraction). Deterministic. It
    proves the wrapper carries nanoseconds — and only that: a production seam that
    truncated would still pass, because pinning replaces it. That is why there is a
    second leg.
  • live — the real clock runs and only properties are asserted: over 2000
    consecutive reads, 0 <= nsec < 1e9, 0 <= usec < 1e6, nsec / 1000 == usec,
    0 <= subsec < 1, to_i <= to_f < to_i + 1, and no read earlier than the one
    before it. Then liveness: a single Time.now may legitimately land on a whole
    second, so no single sample is asserted
    — it samples until it sees a non-zero
    sub-second or a 3-second budget expires. On any clock with better than
    one-second resolution that happens on the first or second sample; the budget is
    spent only when the property is false, which is the defect. A fixed-N "at least
    one of N" would have been a probabilistic assertion; sampling-to-first-witness is
    not.

Elapsed time is asserted the same way: sleep 0.05 between two Time.now reads,
then 0.0 < d < 30.0 — a lower bound the runtime's own timer guarantees and an
upper bound no loaded machine reaches, never a duration literal.

A/B against the old code, three mutations that each compile:

mutation caught by
nowWall = func() time.Time { return time.Unix(time.Now().Unix(), 0) } (the original behaviour) TestTimeNowLiveSubSecondProperties, TestTimeNowMeasuresElapsedTime
timecopInstant back to time.Unix(v.Unix(), 0).UTC() TestTimecopFreezeKeepsSubSecond
Time#- back to a.t.Sub(bt.t).Seconds() TestTimeMinusTimeIsExact

As designed, the pinned leg catches none of mutation 1 — recorded here rather than
presented as coverage.

Every expected value in the pinned and arithmetic tests was read off MRI 4.0.5, not
computed by hand. One expectation I first wrote from my own arithmetic
(Time.at(1600000000.25).to_f == 1600000000.25) is false in MRI too, which
renders that instant's to_f as 1600000000.2499998; the test now asserts #to_r
((6400000001/4)), which is exact and has no rendering subtleties.

Wider clock audit

Each row match/divergence against MRI 4.0.5 on this host.

Match after this change: Time.now/Time.new/Time.now(in:) sub-second;
Time.at with Integer, Float, Rational, (sec, usec) and (sec, ns, :nanosecond);
Time.at(aTime); Time#+/#- including exact Rational shifts;
Time#round/#floor/#ceil at digits 0 and 3; subsec, to_r, %N, %6N;
Process.clock_gettime(CLOCK_REALTIME | CLOCK_MONOTONIC) in :float_second and
:nanosecond (sub-second, ordered, and REALTIME agrees with Time.now to < 1 s);
Kernel#sleep granularity (0.05 s measured through both the monotonic clock and,
now, the wall clock) and its Integer return; File.mtime == File.stat(…).mtime;
Date.today; DateTime.now.

Divergences left open — outside this PR's cluster, not touched here:

  1. File::Stat#mtime/#atime/#ctime/#birthtime truncate to whole seconds.
    internal/vm/filestat.go: statTimestamps reduces every timestamp to
    fi.ModTime().Unix() (int64 seconds) and statTime(unix int64) rebuilds a
    Time from seconds alone, so File.stat(f).mtime.nsec is always 0 where MRI
    reports the filesystem's nanoseconds. Same shape of defect as this one — a
    seconds-typed carrier — in a different subsystem; the Atimespec/Ctimespec
    reflection would have to carry Nsec too.
  2. Four Process::CLOCK_* constants are missing:
    CLOCK_PROCESS_CPUTIME_ID, CLOCK_THREAD_CPUTIME_ID, CLOCK_MONOTONIC_RAW,
    CLOCK_UPTIME_RAW all raise NameError (internal/vm/process.go defines only
    CLOCK_REALTIME and CLOCK_MONOTONIC).
  3. An unknown clock id silently returns the wall clock.
    Process.clock_gettime(999) returns a REALTIME reading; MRI raises
    Errno::EINVAL, "Invalid argument - clock_gettime(999)". The default: branch
    in clock_gettime treats every unrecognised id as REALTIME — a wrong answer
    where MRI refuses, which is the same failure mode as this issue: a plausible
    number instead of an error.

Process.clock_gettime(CLOCK_MONOTONIC) returns seconds since process start where
MRI's is machine uptime. MRI documents the monotonic origin as unspecified, so this
is not counted as a divergence.

bench/*.rb

Checked, and the answer is the good one: nothing in bench/ was reading zero.

  • bench/run.sh times from the shell (/usr/bin/time -p, best of N runs), never
    from Ruby, so the differential table was never affected.
  • bench/modules/benchmark.rb is the only bench that touches timing at all, and it
    deliberately checksums the work rather than the clock ("no wall-clock value
    used" in its own comment); its assertion is tms.is_a?(Benchmark::Tms).
  • Benchmark.measure { … }.real and Benchmark.realtime { … } were already
    positive before this change: internal/vm/benchmark.go reads the monotonic
    source behind Process.clock_gettime(CLOCK_MONOTONIC), not Time.now.
  • No .rb file in the repo outside the vendored spec corpus uses Time.now to
    measure an interval.

So the instrument that was lying was the one users write by hand, and the issue's
own reproduction is the evidence for it; the repo's harness happened to be immune
because it measures from outside.

Gates

  • CGO_ENABLED=0 GOWORK=off go test -count=1 ./... — full suite green.

  • CGO_ENABLED=0 go build ./..., GOOS=wasip1 GOARCH=wasm, GOOS=js GOARCH=wasm —
    all three build. On wasm the change is a resolution change, not a behaviour
    change
    : no build tag decides it, both targets call the same time.Now().
    wasip1 gets clock_time_get nanoseconds; js/wasm gets Date.now()
    milliseconds, so there the sub-second is a multiple of 1e6 — non-zero, ordered,
    and within every invariant the tests assert, which is why the live test asserts
    ranges and a witness rather than nanosecond distinctness.

  • gofmt -l internal/ cmd/ — empty.

  • ruby/spec ratchet, corpus pinned 87b1631 at
    /Users/Shared/rbgo-measure/rubyspec-corpus, TIMEOUT=25, /tmp/rbgo-rubyspec
    removed before each run, both trees measured back to back on an idle machine:

    tree compiled HEAD passing examples
    origin/main (clean worktree) 8f2a019b 23179
    this branch 9c73ffc3 23181

    +2, and both above the frozen floor 23113 (which origin/main already clears
    by 66 — the floor is the reporter's to move, untouched here). The two examples
    are attributable, not run-to-run noise: comparing per-file pass counts with the
    two binaries, core/time/new_spec.rb goes 112 → 113 and core/time/now_spec.rb
    16 → 17, and no other file in core/time or core/process moves.

    Sweep integrity, since rows-equals-inputs is not sufficient: the population is
    language + core, 2206 *_spec.rb files, 2206 distinct paths; each
    run reports 2198 loaded + 8 failed to load = 2206, the same 8 in both trees; and
    the measurement is floored (a run that read files but scored nothing would fail
    the ratchet, not pass it).

  • Coverage — measured with the toolchain the gate uses. The first profiles here
    were taken with the host default Go 1.26.4, which counts fewer basic blocks than
    CI's Go 1.27.1 and so can only give an upper bound (The coverage gate cannot be reproduced locally (Go 1.26 counts 404 blocks where CI's 1.27 counts 414) and has no rounding headroom left #704). Re-measured with
    ~/.pkgx/go.dev/v1.27.1/bin/go, -coverpkg=$(go list ./internal/...), one
    profile per tree, each go tool cover -func resolved in the tree that produced
    its profile
    .

    The criterion applied is "the below-100 list is unchanged", not a 100.0%
    reading, since the total only rounds to one decimal.

    • CI's own lane, which is the judge: the ubuntu below-100 list for this PR
      (run 36271161184, Go 1.27.1, 19 entries) is byte-identical to the
      ubuntu list for main's content — taken from the ubuntu lane of Raise the ruby/spec floor 22475 -> 23113 after waves 33-36 #696
      (run 36261499627), whose head 8ebbb1d6 differs from 8f2a019b only in the
      FLOOR file and so has the same Go code. Both lanes print coverage: 100.0%.
    • CI's macOS lane, the other gated one: 16 entries for this PR and the same
      16, identical, for main's content, both at coverage: 100.0%.
    • Locally under Go 1.27.1 on macOS: 16 entries, the same list again, and
      again identical between origin/main (8f2a019b, clean separate worktree)
      and this branch (9c73ffc3). The local macOS list agrees with CI's macOS list
      entry for entry, which is the check that the local tool is counting like the
      gate. The 16/19 difference between the lanes is the lane, not the change —
      dir.go cwdStillNamed, filestat.go Inspect and filestat.go registerFileStat appear only on the linux lane.
    • None of the below-100 entries, on either lane, is in time.go, timecop.go or
      vm.go; every one is present on unmodified main, and two sit at 0.0%
      (bigdecimal_bind.go:Inspect, date_bind.go:Inspect).
    • Full measured function set (Go 1.27.1 profiles): exactly one addition,
      internal/vm/time.go exactSeconds at 100.0%, and zero removals — nothing
      orphaned, 7325 → 7326 functions.
    • Every function this PR touches measures 100.0% under 1.27.1: timeNow,
      timeNew, timeArith, shiftByRat, subsecRat, exactSeconds,
      nowInstant, timeFromInstant, timecopInstant, NewWithStderr. Go 1.27.1
      exposed no new uncovered block in this change, so there was no
      reachable-or-dead question to answer here.
  • Pre-existence of the below-100 entries was proved on a clean origin/main
    checkout in a separate worktree
    (~/rbgo-wt43/main-clean, detached at
    8f2a019b), not by stashing.

🤖 Generated with Claude Code

Time.now returned a whole second, so the universal Ruby elapsed-time idiom
`t = Time.now; work; Time.now - t` measured 0.0 no matter how long the work
took. A measuring instrument that answers a plausible zero is worse than one
that crashes, because zero reads as good news.

The truncation was in the *type* of the clock seam, not in Time.now's body:

    var nowUnix = func() int64 { return stdtime.Now().Unix() }
    vm.clock = timecop.NewWith(func() stdtime.Time {
        return stdtime.Unix(nowUnix(), 0).UTC()
    })

A seconds-typed seam is whole-second for every reader, whatever the readers do,
and the clock has four of them: Time.now, Time.new (no args), Date.today and
DateTime.now. The seam now hands back a whole instant (nowWall), which is what
MRI's time_s_now -> rb_time_timespec_now -> clock_gettime(CLOCK_REALTIME) keeps
in tv_nsec. The Time representation already carried nanoseconds exactly, so
nothing downstream needed changing.

Two further sub-second losses on the same path, found by auditing it:

  * Timecop.freeze/travel resolved a Time argument through
    time.Unix(v.Unix(), 0), so freezing at an instant carrying a sub-second
    silently moved the clock back to the start of that second;
  * Time#- (Time minus Time) went through time.Time.Sub, whose time.Duration is
    nanosecond-granular, dropping the sub-nanosecond remainder a Time keeps in
    frac: (t + 0.000001) - t read 9.99e-07 where MRI reads 1.0e-06. It is now
    the exact rational difference, converted to Float once.

Time is the one subject where a test must not assert a literal, so the new tests
assert properties (range, internal agreement, ordering, a positive elapsed
interval) plus a pinned-seam leg whose expectations were each read off MRI
4.0.5. The live leg samples until it sees a non-zero sub-second rather than
trusting one sample, which can legitimately be zero.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Time.now truncates to a whole second, so every Ruby-level elapsed-time measurement reads 0.0

1 participant