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)
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.
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
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.
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).
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).
$ 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.
