Time::precise_time_ns is overflowing today in WSL

One of my Rust experiments, which had been working well for ages, surprised me by not starting this morning. Producing a panic that I can reproduce as follows:

$ cat src/main.rs
use time::precise_time_ns;

fn main() {
    let start_time = precise_time_ns();

    println!("{}", start_time);
}

$ rustup default stable
info: using existing install for 'stable-x86_64-unknown-linux-gnu'
info: default toolchain set to 'stable-x86_64-unknown-linux-gnu'

  stable-x86_64-unknown-linux-gnu unchanged - rustc 1.39.0 (4560ea788 2019-11-04)

$ cargo clean
$ cargo run
   Compiling libc v0.2.66
   Compiling time v0.1.42
   Compiling rust_time_bug v0.1.0 (/mnt/c/Users/michael/rust_time_bug)
    Finished dev [unoptimized + debuginfo] target(s) in 5.62s
     Running `target/debug/rust_time_bug`
thread 'main' panicked at 'attempt to multiply with overflow', /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/time-0.1.42/src/sys.rs:581:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.

The line in 'time' referred to is:

            (ts.tv_sec as u64) * 1000000000 + (ts.tv_nsec as u64) 

Does the same in nightly as well.

Where can I report such a bug.

1 Like

As the bug seems to be from the "time" crate, I would report this in the associated repository.

i wonder what happens there (can any of the ts values be negative ?)
if i get it right, u64 for nanoseconds since epoch should theoretically be good until Sun Jul 21 23:34:33 2554 UTC

Seems so. Adding a println to the offending line I get:

            println!("ts.tv_sec = {}", ts.tv_sec);
            (ts.tv_sec as u64) * 1000000000 + (ts.tv_nsec as u64)
$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `target/debug/rust_time_bug`
ts.tv_sec: -3337660
thread 'main' panicked at 'attempt to multiply with overflow', /home/michael/.cargo/registry/src/github.com-1ecc6299db9ec823/time-0.1.42/src/sys.rs:581:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
1 Like

ohh it's CLOCK_MONOTONIC, right, there's no guarantee that the returned date/times make sense beyond differences

1 Like

That is right. I was using it as a crude benchmark timer so I only need differences.

1 Like

So I rebooted my Windows 10 machine and restarted the Linux subsystem.

Sure enough procise_time_ns() started to work again:

$ cargo clean
michael@monster:/mnt/c/Users/michael/rust_time_bug$ cargo run --release
   Compiling libc v0.2.66
   Compiling time v0.1.42
   Compiling rust_time_bug v0.1.0 (/mnt/c/Users/michael/rust_time_bug)
    Finished release [optimized] target(s) in 5.07s
     Running `target/release/rust_time_bug`
ts.tv_sec = 261
ts.tv_nsec = 202315000
261202315000

So where is the bug? In 'time', in Debian, in the Linux Subsystem, in Windows 10?

Grrrr...

the assumption in the time crate that it has a positive value is wrong: the monotonic clock can start at any arbitrary value at boot, including negative ones

this complicates things: because its range is the full integer range, this makes it impossible to fit this value in a u64 generally (at least on systems where time_t is 64 bit, when it's 32 bit one could just add 2^31?)

i guess changing the * to a wrapping_mul would be a correct solution, but only with the assumption that client code uses wrapping_sub to get differences, which is probably a wrong assumption :woman_shrugging:

2 Likes

Why not just use an i64 ?

Bug reported: https://github.com/time-rs/time/issues/192

2 Likes

the structure returned is like this:

struct timespec {
       time_t   tv_sec;        /* seconds */
       long     tv_nsec;       /* nanoseconds */
}

in the case that the time_t is an arbitrary 64-bit signed integer (which seems to be the case with the monotonic clock here), multiplying with 1e9 can cause an overflow

otoh, the manual page for clock_gettime says:

       CLOCK_MONOTONIC
              Clock  that  cannot  be set and represents monotonic time since some unspecified starting
              point.  This clock is not affected by discontinuous jumps in the system  time  (e.g.,  if
              the  system administrator manually changes the clock), but is affected by the incremental
              adjustments performed by adjtime(3) and NTP.

this doesn't mention negative values, at all

2 Likes

I see. How about an i128, then ? :wink:

2 Likes

Or use a more appropriate interface such as Instant::elapsed for measuring timespans, then you are guaranteed that the resulting Duration can be represented as an i64 number of nanoseconds (assume you're not coding for the long now).

6 Likes

To be clear my issue here not to do with measuring time spans. The problem is with reading the time in the first place. Which on Unix uses clock_gettime(). That overflow panic would have occurred if I was using Instant::elapsed as well.

I have noticed while using WSL2 that it's very common for my WSL system time to get extremely out of date (especially when I sleep my computer). I would guess that this has something to do with the problem. hwclock --hctosys resets the time to your Windows native time, so maybe that would help work around this problem for you.

Do you mean that WSL has a buggy implementation of CLOCK_MONOTONIC which would have made Instant::elapsed panic?

Instant::elapsed is guaranteed to at most ever return the time the system has been on (+ minor adjustments), which gives it a range of something like 3 centuries when converted into i64 nanoseconds. Instant itself is not allowed to have discontinuous jumps, the values it wraps are arbitrary, but have a strict relationship when requested within the same process (which the API limits you to doing).

Sadly it does not:

$ sudo hwclock --hctosys
hwclock: Cannot access the Hardware Clock via any known method.
hwclock: Use the --verbose option to see the details of our search for an access method.
$
$ sudo hwclock --hctosys --verbose
hwclock from util-linux 2.33.1
System Time: 1575386022.916245
Trying to open: /dev/rtc0
Trying to open: /dev/rtc
Trying to open: /dev/misc/rtc
No usable clock interface found.
hwclock: Cannot access the Hardware Clock via any known method.

Are you on WSL or WSL2? Can you check if your time inside WSL matches your host time (especially after sleeping your computer for a while)? This may in the end be unrelated to the behavior I've observed.

hwclock is not going to help here; (edit: discontinuous) adjustments in the system clock do not modify the monotonic clock, by definition

1 Like

I'm not totally sure but the 'time' documentation says it uses clock_gettime() on Unix.

The code that panicked in time::precise_time_ns() today does this with the value returned by clock_time_get():

(ts.tv_sec as u64) * 1000000000 + (ts.tv_nsec as u64)

As ts.tv_sec was negative, see above, it panicked.

I assume that when using Instant::elapsed() one is still ends up calling clock_gettime() somewhere with the same issue.