Skip to content

Commit d130e41

Browse files
authored
Rollup merge of rust-lang#57380 - bearcage:master, r=alexcrichton
Fix Instant/Duration math precision & associativity on Windows **tl;dr** Addition and subtraction on Duration/Instant are not associative on windows because we use the perfcounter frequency in every calculation instead of just when we measure time. This is my first contrib (PR or Issue) to Rust, so please lmk if I've done this wrong. I followed CONTRIBUTING to the extent I could given my system doesn't seem to be able to build the compiler with changes in the source tree. I also asked about this issue in #rust-beginners a week or so ago, before digging through libstd -- I'm unsure if there's a good way to follow up on that, but I'd be happy to update the docs on the timing structs if this fixes the problem. ## Issue The `Duration` type keeps seconds in the upper-64 and nanoseconds in the lower-32 bits. In theory doing math on these ought to be basically the same as doing math on any other 64 or 32 bit integral number. On windows (and I think macos too), however, our math gets messy because the Instant type stores the current point in time in units of HPET Performance Counter counts, not nanoseconds, and does unit conversions on every math operation, rather than just when we measure the time from the system clock. I tried this code: ``` use std::time::{Duration, Instant}; fn main() { let now = Instant::now(); let offset = Duration::from_millis(5); assert_eq!((now + offset) - now, (now - now) + offset); } ``` On UNIX machines (linux and macos) it behaves as you'd expect -- [no crash](https://play.rust-lang.org/?version=stable&mode=debug&edition=2018&gist=cf2206c0b7e07d8ecc7767a512364094). On Windows hosts, however, it blows up because of a precision problem in the Instant +/- Duration math: ``` C:\Users\aberg\work\timetest (master -> origin) λ cargo run Finished dev [unoptimized + debuginfo] target(s) in 0.02s Running `target\debug\timetest.exe` thread 'main' panicked at 'assertion failed: `(left == right)` left: `4.999914ms`, right: `5ms`', src\main.rs:6:5 note: Run with `RUST_BACKTRACE=1` for a backtrace. error: process didn't exit successfully: `target\debug\timetest.exe` (exit code: 101) C:\Users\aberg\work\timetest (master -> origin) λ cat src\main.rs use std::time::{Duration, Instant}; fn main() { let now = Instant::now(); let offset = Duration::from_millis(5); assert_eq!((now + offset) - now, (now - now) + offset); } ``` On windows I think this is a consequence of doing the HPET-PerfCounter-Unit conversion on each math operation. I suspect the reason it works on macs is that (from what I could find online) most apple machines report timing in nanoseconds anyway. For anyone interested, the equivalent functions on macos, with a little work to fish out the numerator/denominator from a timebase struct: * `QueryPerformanceCounter()` -> `mach_absolute_time()` * `QueryPerformanceFrequency()` -> `mach_timebase_info()` If this PR ends up working as I expect it to when CI runs the tests, I can make the same changes to the macos implementation. ## Potential Fix We ought to be able to sort this out by storing nanoseconds, rather than PerfCounter units, that way intermediate math is done in the most precise units we support and we're only doing unit conversions when we actually measure the system clock (and it might even translate to a small perf gain for people doing tons of Instant/Duration math). I believe this will address the underlying cause of rust-lang#56034, and make the guessed epsilon constant from rust-lang#56059 unnecessary. If it's of interest, I can write up how these timing types work on the tier 1 platforms to address rust-lang#32626 as well, since I'm already in here figuring it out. ## This Patch To that end, I've got this patch, which I think should fix it on windows, but I'm having trouble testing it -- any time I change anything in libstd I start getting this error, which no amount of clean building seems to resolve: ``` C:\Users\aberg\work\rust (master -> origin) λ python x.py test --stage 0 --no-doc src/libstd Updating only changed submodules Submodules updated in 0.27 seconds Finished dev [unoptimized] target(s) in 2.41s Building stage0 std artifacts (x86_64-pc-windows-msvc -> x86_64-pc-windows-msvc) Finished release [optimized] target(s) in 6.78s Copying stage0 std from stage0 (x86_64-pc-windows-msvc -> x86_64-pc-windows-msvc / x86_64-pc-windows-msvc) Building stage0 test artifacts (x86_64-pc-windows-msvc -> x86_64-pc-windows-msvc) Compiling test v0.0.0 (C:\Users\aberg\work\rust\src\libtest) error[E0460]: found possibly newer version of crate `std` which `getopts` depends on --> src\libtest\lib.rs:36:1 | 36 | extern crate getopts; | ^^^^^^^^^^^^^^^^^^^^^ | = note: perhaps that crate needs to be recompiled? = note: the following crate versions were found: crate `std`: \\?\C:\Users\aberg\work\rust\build\x86_64-pc-windows-msvc\stage0-sysroot\lib\rustlib\x86_64-pc-windows-msvc\lib\libstd-d7a80ca2ae113c97.rlib crate `std`: \\?\C:\Users\aberg\work\rust\build\x86_64-pc-windows-msvc\stage0-sysroot\lib\rustlib\x86_64-pc-windows-msvc\lib\std-d7a80ca2ae113c97.dll crate `getopts`: \\?\C:\Users\aberg\work\rust\build\x86_64-pc-windows-msvc\stage0-test\x86_64-pc-windows-msvc\release\deps\libgetopts-ae40a96de5f5d144.rlib error: aborting due to previous error For more information about this error, try `rustc --explain E0460`. error: Could not compile `test`. To learn more, run the command again with --verbose. command did not execute successfully: "C:\\Users\\aberg\\work\\rust\\build\\x86_64-pc-windows-msvc\\stage0\\bin\\cargo.exe" "build" "--target" "x86_64-pc-windows-msvc" "-j" "12" "--release" "--manifest-path" "C:\\Users\\aberg\\work\\rust\\src/libtest/Cargo.toml" "--message-format" "json" expected success, got: exit code: 101 failed to run: C:\Users\aberg\work\rust\build\bootstrap\debug\bootstrap test --stage 0 --no-doc src/libstd Build completed unsuccessfully in 0:00:20 ``` --- Since you wrote the linked PRs and might remember looking at related problems: r? @alexcrichton
2 parents 095b44c + 14ce536 commit d130e41

File tree

2 files changed

+83
-44
lines changed

2 files changed

+83
-44
lines changed

src/libstd/sys/windows/time.rs

+74-44
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,7 @@
11
use cmp::Ordering;
22
use fmt;
33
use mem;
4-
use sync::Once;
54
use sys::c;
6-
use sys::cvt;
7-
use sys_common::mul_div_u64;
85
use time::Duration;
96
use convert::TryInto;
107
use core::hash::{Hash, Hasher};
@@ -14,7 +11,9 @@ const INTERVALS_PER_SEC: u64 = NANOS_PER_SEC / 100;
1411

1512
#[derive(Copy, Clone, Eq, PartialEq, Ord, PartialOrd, Debug, Hash)]
1613
pub struct Instant {
17-
t: c::LARGE_INTEGER,
14+
// This duration is relative to an arbitrary microsecond epoch
15+
// from the winapi QueryPerformanceCounter function.
16+
t: Duration,
1817
}
1918

2019
#[derive(Copy, Clone)]
@@ -33,59 +32,44 @@ pub const UNIX_EPOCH: SystemTime = SystemTime {
3332

3433
impl Instant {
3534
pub fn now() -> Instant {
36-
let mut t = Instant { t: 0 };
37-
cvt(unsafe {
38-
c::QueryPerformanceCounter(&mut t.t)
39-
}).unwrap();
40-
t
35+
// High precision timing on windows operates in "Performance Counter"
36+
// units, as returned by the WINAPI QueryPerformanceCounter function.
37+
// These relate to seconds by a factor of QueryPerformanceFrequency.
38+
// In order to keep unit conversions out of normal interval math, we
39+
// measure in QPC units and immediately convert to nanoseconds.
40+
perf_counter::PerformanceCounterInstant::now().into()
4141
}
4242

4343
pub fn actually_monotonic() -> bool {
4444
false
4545
}
4646

4747
pub const fn zero() -> Instant {
48-
Instant { t: 0 }
48+
Instant { t: Duration::from_secs(0) }
4949
}
5050

5151
pub fn sub_instant(&self, other: &Instant) -> Duration {
52-
// Values which are +- 1 need to be considered as basically the same
53-
// units in time due to various measurement oddities, according to
54-
// Windows [1]
55-
//
56-
// [1]:
57-
// https://msdn.microsoft.com/en-us/library/windows/desktop
58-
// /dn553408%28v=vs.85%29.aspx#guidance
59-
if other.t > self.t && other.t - self.t == 1 {
52+
// On windows there's a threshold below which we consider two timestamps
53+
// equivalent due to measurement error. For more details + doc link,
54+
// check the docs on epsilon.
55+
let epsilon =
56+
perf_counter::PerformanceCounterInstant::epsilon();
57+
if other.t > self.t && other.t - self.t <= epsilon {
6058
return Duration::new(0, 0)
6159
}
62-
let diff = (self.t as u64).checked_sub(other.t as u64)
63-
.expect("specified instant was later than \
64-
self");
65-
let nanos = mul_div_u64(diff, NANOS_PER_SEC, frequency() as u64);
66-
Duration::new(nanos / NANOS_PER_SEC, (nanos % NANOS_PER_SEC) as u32)
60+
self.t.checked_sub(other.t)
61+
.expect("specified instant was later than self")
6762
}
6863

6964
pub fn checked_add_duration(&self, other: &Duration) -> Option<Instant> {
70-
let freq = frequency() as u64;
71-
let t = other.as_secs()
72-
.checked_mul(freq)?
73-
.checked_add(mul_div_u64(other.subsec_nanos() as u64, freq, NANOS_PER_SEC))?
74-
.checked_add(self.t as u64)?;
7565
Some(Instant {
76-
t: t as c::LARGE_INTEGER,
66+
t: self.t.checked_add(*other)?
7767
})
7868
}
7969

8070
pub fn checked_sub_duration(&self, other: &Duration) -> Option<Instant> {
81-
let freq = frequency() as u64;
82-
let t = other.as_secs().checked_mul(freq).and_then(|i| {
83-
(self.t as u64).checked_sub(i)
84-
}).and_then(|i| {
85-
i.checked_sub(mul_div_u64(other.subsec_nanos() as u64, freq, NANOS_PER_SEC))
86-
})?;
8771
Some(Instant {
88-
t: t as c::LARGE_INTEGER,
72+
t: self.t.checked_sub(*other)?
8973
})
9074
}
9175
}
@@ -186,14 +170,60 @@ fn intervals2dur(intervals: u64) -> Duration {
186170
((intervals % INTERVALS_PER_SEC) * 100) as u32)
187171
}
188172

189-
fn frequency() -> c::LARGE_INTEGER {
190-
static mut FREQUENCY: c::LARGE_INTEGER = 0;
191-
static ONCE: Once = Once::new();
173+
mod perf_counter {
174+
use super::{NANOS_PER_SEC};
175+
use sync::Once;
176+
use sys_common::mul_div_u64;
177+
use sys::c;
178+
use sys::cvt;
179+
use time::Duration;
180+
181+
pub struct PerformanceCounterInstant {
182+
ts: c::LARGE_INTEGER
183+
}
184+
impl PerformanceCounterInstant {
185+
pub fn now() -> Self {
186+
Self {
187+
ts: query()
188+
}
189+
}
192190

193-
unsafe {
194-
ONCE.call_once(|| {
195-
cvt(c::QueryPerformanceFrequency(&mut FREQUENCY)).unwrap();
196-
});
197-
FREQUENCY
191+
// Per microsoft docs, the margin of error for cross-thread time comparisons
192+
// using QueryPerformanceCounter is 1 "tick" -- defined as 1/frequency().
193+
// Reference: https://docs.microsoft.com/en-us/windows/desktop/SysInfo
194+
// /acquiring-high-resolution-time-stamps
195+
pub fn epsilon() -> Duration {
196+
let epsilon = NANOS_PER_SEC / (frequency() as u64);
197+
Duration::from_nanos(epsilon)
198+
}
199+
}
200+
impl From<PerformanceCounterInstant> for super::Instant {
201+
fn from(other: PerformanceCounterInstant) -> Self {
202+
let freq = frequency() as u64;
203+
let instant_nsec = mul_div_u64(other.ts as u64, NANOS_PER_SEC, freq);
204+
Self {
205+
t: Duration::from_nanos(instant_nsec)
206+
}
207+
}
208+
}
209+
210+
fn frequency() -> c::LARGE_INTEGER {
211+
static mut FREQUENCY: c::LARGE_INTEGER = 0;
212+
static ONCE: Once = Once::new();
213+
214+
unsafe {
215+
ONCE.call_once(|| {
216+
cvt(c::QueryPerformanceFrequency(&mut FREQUENCY)).unwrap();
217+
});
218+
FREQUENCY
219+
}
220+
}
221+
222+
fn query() -> c::LARGE_INTEGER {
223+
let mut qpc_value: c::LARGE_INTEGER = 0;
224+
cvt(unsafe {
225+
c::QueryPerformanceCounter(&mut qpc_value)
226+
}).unwrap();
227+
qpc_value
198228
}
199229
}

src/libstd/time.rs

+9
Original file line numberDiff line numberDiff line change
@@ -610,6 +610,15 @@ mod tests {
610610
assert_eq!(a + year, a.checked_add(year).unwrap());
611611
}
612612

613+
#[test]
614+
fn instant_math_is_associative() {
615+
let now = Instant::now();
616+
let offset = Duration::from_millis(5);
617+
// Changing the order of instant math shouldn't change the results,
618+
// especially when the expression reduces to X + identity.
619+
assert_eq!((now + offset) - now, (now - now) + offset);
620+
}
621+
613622
#[test]
614623
#[should_panic]
615624
fn instant_duration_panic() {

0 commit comments

Comments
 (0)