squiid/rust
1
0
Fork 0
Code Issues Pull requests Projects Activity

Rollup merge of #57380 - bearcage:master, r=alexcrichton

Browse source 
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 #56034, and make the guessed epsilon constant from #56059 unnecessary. If it's of interest, I can write up how these timing types work on the tier 1 platforms to address #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
This commit is contained in:
Mazdak Farrokhzad 2019-01-24 18:25:41 +01:00 committed by GitHub
commit d130e41423
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 83 additions and 44 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

118
src/libstd/sys/windows/time.rs
View file

@ -1,10 +1,7 @@
use cmp::Ordering;
use fmt;
use mem;
use sync::Once;
use sys::c;
use sys::cvt;
use sys_common::mul_div_u64;
use time::Duration;
use convert::TryInto;
use core::hash::{Hash, Hasher};
@ -14,7 +11,9 @@ const INTERVALS_PER_SEC: u64 = NANOS_PER_SEC / 100;
#[derive(Copy, Clone, Eq, PartialEq, Ord, PartialOrd, Debug, Hash)]
pub struct Instant {
t: c::LARGE_INTEGER,
// This duration is relative to an arbitrary microsecond epoch
// from the winapi QueryPerformanceCounter function.
t: Duration,
}
#[derive(Copy, Clone)]
@ -33,11 +32,12 @@ pub const UNIX_EPOCH: SystemTime = SystemTime {
impl Instant {
pub fn now() -> Instant {
let mut t = Instant { t: 0 };
cvt(unsafe {
c::QueryPerformanceCounter(&mut t.t)
}).unwrap();
t
// High precision timing on windows operates in "Performance Counter"
// units, as returned by the WINAPI QueryPerformanceCounter function.
// These relate to seconds by a factor of QueryPerformanceFrequency.
// In order to keep unit conversions out of normal interval math, we
// measure in QPC units and immediately convert to nanoseconds.
perf_counter::PerformanceCounterInstant::now().into()
}
pub fn actually_monotonic() -> bool {
@ -45,47 +45,31 @@ impl Instant {
}
pub const fn zero() -> Instant {
Instant { t: 0 }
Instant { t: Duration::from_secs(0) }
}
pub fn sub_instant(&self, other: &Instant) -> Duration {
// Values which are +- 1 need to be considered as basically the same
// units in time due to various measurement oddities, according to
// Windows [1]
//
// [1]:
// https://msdn.microsoft.com/en-us/library/windows/desktop
// /dn553408%28v=vs.85%29.aspx#guidance
if other.t > self.t && other.t - self.t == 1 {
// On windows there's a threshold below which we consider two timestamps
// equivalent due to measurement error. For more details + doc link,
// check the docs on epsilon.
let epsilon =
perf_counter::PerformanceCounterInstant::epsilon();
if other.t > self.t && other.t - self.t <= epsilon {
return Duration::new(0, 0)
}
let diff = (self.t as u64).checked_sub(other.t as u64)
.expect("specified instant was later than \
self");
let nanos = mul_div_u64(diff, NANOS_PER_SEC, frequency() as u64);
Duration::new(nanos / NANOS_PER_SEC, (nanos % NANOS_PER_SEC) as u32)
self.t.checked_sub(other.t)
.expect("specified instant was later than self")
}
pub fn checked_add_duration(&self, other: &Duration) -> Option<Instant> {
let freq = frequency() as u64;
let t = other.as_secs()
.checked_mul(freq)?
.checked_add(mul_div_u64(other.subsec_nanos() as u64, freq, NANOS_PER_SEC))?
.checked_add(self.t as u64)?;
Some(Instant {
t: t as c::LARGE_INTEGER,
t: self.t.checked_add(*other)?
})
}
pub fn checked_sub_duration(&self, other: &Duration) -> Option<Instant> {
let freq = frequency() as u64;
let t = other.as_secs().checked_mul(freq).and_then(|i| {
(self.t as u64).checked_sub(i)
}).and_then(|i| {
i.checked_sub(mul_div_u64(other.subsec_nanos() as u64, freq, NANOS_PER_SEC))
})?;
Some(Instant {
t: t as c::LARGE_INTEGER,
t: self.t.checked_sub(*other)?
})
}
}
@ -186,14 +170,60 @@ fn intervals2dur(intervals: u64) -> Duration {
((intervals % INTERVALS_PER_SEC) * 100) as u32)
}
fn frequency() -> c::LARGE_INTEGER {
static mut FREQUENCY: c::LARGE_INTEGER = 0;
static ONCE: Once = Once::new();
mod perf_counter {
use super::{NANOS_PER_SEC};
use sync::Once;
use sys_common::mul_div_u64;
use sys::c;
use sys::cvt;
use time::Duration;
unsafe {
ONCE.call_once(|| {
cvt(c::QueryPerformanceFrequency(&mut FREQUENCY)).unwrap();
});
FREQUENCY
pub struct PerformanceCounterInstant {
ts: c::LARGE_INTEGER
}
impl PerformanceCounterInstant {
pub fn now() -> Self {
Self {
ts: query()
}
}
// Per microsoft docs, the margin of error for cross-thread time comparisons
// using QueryPerformanceCounter is 1 "tick" -- defined as 1/frequency().
// Reference: https://docs.microsoft.com/en-us/windows/desktop/SysInfo
// /acquiring-high-resolution-time-stamps
pub fn epsilon() -> Duration {
let epsilon = NANOS_PER_SEC / (frequency() as u64);
Duration::from_nanos(epsilon)
}
}
impl From<PerformanceCounterInstant> for super::Instant {
fn from(other: PerformanceCounterInstant) -> Self {
let freq = frequency() as u64;
let instant_nsec = mul_div_u64(other.ts as u64, NANOS_PER_SEC, freq);
Self {
t: Duration::from_nanos(instant_nsec)
}
}
}
fn frequency() -> c::LARGE_INTEGER {
static mut FREQUENCY: c::LARGE_INTEGER = 0;
static ONCE: Once = Once::new();
unsafe {
ONCE.call_once(|| {
cvt(c::QueryPerformanceFrequency(&mut FREQUENCY)).unwrap();
});
FREQUENCY
}
}
fn query() -> c::LARGE_INTEGER {
let mut qpc_value: c::LARGE_INTEGER = 0;
cvt(unsafe {
c::QueryPerformanceCounter(&mut qpc_value)
}).unwrap();
qpc_value
}
}

9
src/libstd/time.rs
View file

@ -610,6 +610,15 @@ mod tests {
assert_eq!(a + year, a.checked_add(year).unwrap());
}
#[test]
fn instant_math_is_associative() {
let now = Instant::now();
let offset = Duration::from_millis(5);
// Changing the order of instant math shouldn't change the results,
// especially when the expression reduces to X + identity.
assert_eq!((now + offset) - now, (now - now) + offset);
}
#[test]
#[should_panic]
fn instant_duration_panic() {