From 9eeb13fdd1c10de7f489e7fc910686c6d492398e Mon Sep 17 00:00:00 2001 From: Lukas Kalbertodt Date: Sun, 6 May 2018 13:46:20 +0200 Subject: [PATCH 1/3] Improve `Debug` impl of `core::time::Duration` MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Prior to this, Duration simply derived Debug. Since Duration doesn't implement `Display`, the only way to inspect its value is to use `Debug`. Unfortunately, the derived `Debug` impl is far from optimal for humans. In many cases, Durations are used for some quick'n'dirty benchmarking (or in general: measuring the time of some code). Correctly understanding the output of Duration's Debug impl is not easy (e.g. is "{ secs: 0, nanos: 968360102 }" or "{ secs: 0, nanos 98507324 }" shorter?). This commit replaces the derived impl with a manual one. It prints the duration as seconds (i.e. "3.1803s") if the duration is longer than a second, otherwise it prints it in either ms, µs or ns (depending on the duration's length). This already helps readability a lot and it never omits information that is stored. This `Debug` impl does *not* respect the following formatting parameters: - fill/align/padding: difficult to implement, probably not worth it - alternate # flag: not clear what this should do --- src/libcore/tests/time.rs | 112 ++++++++++++++++++++++++++++++++++++++ src/libcore/time.rs | 78 +++++++++++++++++++++++++- 2 files changed, 189 insertions(+), 1 deletion(-) diff --git a/src/libcore/tests/time.rs b/src/libcore/tests/time.rs index 042c523f25f25..bfb5369cf8f8c 100644 --- a/src/libcore/tests/time.rs +++ b/src/libcore/tests/time.rs @@ -122,3 +122,115 @@ fn checked_div() { assert_eq!(Duration::new(1, 0).checked_div(2), Some(Duration::new(0, 500_000_000))); assert_eq!(Duration::new(2, 0).checked_div(0), None); } + +#[test] +fn debug_formatting_extreme_values() { + assert_eq!( + format!("{:?}", Duration::new(18_446_744_073_709_551_615, 123_456_789)), + "18446744073709551615.123456789s" + ); +} + +#[test] +fn debug_formatting_secs() { + assert_eq!(format!("{:?}", Duration::new(7, 000_000_000)), "7s"); + assert_eq!(format!("{:?}", Duration::new(7, 100_000_000)), "7.1s"); + assert_eq!(format!("{:?}", Duration::new(7, 000_010_000)), "7.00001s"); + assert_eq!(format!("{:?}", Duration::new(7, 000_000_001)), "7.000000001s"); + assert_eq!(format!("{:?}", Duration::new(7, 123_456_789)), "7.123456789s"); + + assert_eq!(format!("{:?}", Duration::new(88, 000_000_000)), "88s"); + assert_eq!(format!("{:?}", Duration::new(88, 100_000_000)), "88.1s"); + assert_eq!(format!("{:?}", Duration::new(88, 000_010_000)), "88.00001s"); + assert_eq!(format!("{:?}", Duration::new(88, 000_000_001)), "88.000000001s"); + assert_eq!(format!("{:?}", Duration::new(88, 123_456_789)), "88.123456789s"); + + assert_eq!(format!("{:?}", Duration::new(999, 000_000_000)), "999s"); + assert_eq!(format!("{:?}", Duration::new(999, 100_000_000)), "999.1s"); + assert_eq!(format!("{:?}", Duration::new(999, 000_010_000)), "999.00001s"); + assert_eq!(format!("{:?}", Duration::new(999, 000_000_001)), "999.000000001s"); + assert_eq!(format!("{:?}", Duration::new(999, 123_456_789)), "999.123456789s"); +} + +#[test] +fn debug_formatting_millis() { + assert_eq!(format!("{:?}", Duration::new(0, 7_000_000)), "7ms"); + assert_eq!(format!("{:?}", Duration::new(0, 7_100_000)), "7.1ms"); + assert_eq!(format!("{:?}", Duration::new(0, 7_000_001)), "7.000001ms"); + assert_eq!(format!("{:?}", Duration::new(0, 7_123_456)), "7.123456ms"); + + assert_eq!(format!("{:?}", Duration::new(0, 88_000_000)), "88ms"); + assert_eq!(format!("{:?}", Duration::new(0, 88_100_000)), "88.1ms"); + assert_eq!(format!("{:?}", Duration::new(0, 88_000_001)), "88.000001ms"); + assert_eq!(format!("{:?}", Duration::new(0, 88_123_456)), "88.123456ms"); + + assert_eq!(format!("{:?}", Duration::new(0, 999_000_000)), "999ms"); + assert_eq!(format!("{:?}", Duration::new(0, 999_100_000)), "999.1ms"); + assert_eq!(format!("{:?}", Duration::new(0, 999_000_001)), "999.000001ms"); + assert_eq!(format!("{:?}", Duration::new(0, 999_123_456)), "999.123456ms"); +} + +#[test] +fn debug_formatting_micros() { + assert_eq!(format!("{:?}", Duration::new(0, 7_000)), "7µs"); + assert_eq!(format!("{:?}", Duration::new(0, 7_100)), "7.1µs"); + assert_eq!(format!("{:?}", Duration::new(0, 7_001)), "7.001µs"); + assert_eq!(format!("{:?}", Duration::new(0, 7_123)), "7.123µs"); + + assert_eq!(format!("{:?}", Duration::new(0, 88_000)), "88µs"); + assert_eq!(format!("{:?}", Duration::new(0, 88_100)), "88.1µs"); + assert_eq!(format!("{:?}", Duration::new(0, 88_001)), "88.001µs"); + assert_eq!(format!("{:?}", Duration::new(0, 88_123)), "88.123µs"); + + assert_eq!(format!("{:?}", Duration::new(0, 999_000)), "999µs"); + assert_eq!(format!("{:?}", Duration::new(0, 999_100)), "999.1µs"); + assert_eq!(format!("{:?}", Duration::new(0, 999_001)), "999.001µs"); + assert_eq!(format!("{:?}", Duration::new(0, 999_123)), "999.123µs"); +} + +#[test] +fn debug_formatting_nanos() { + assert_eq!(format!("{:?}", Duration::new(0, 0)), "0ns"); + assert_eq!(format!("{:?}", Duration::new(0, 1)), "1ns"); + assert_eq!(format!("{:?}", Duration::new(0, 88)), "88ns"); + assert_eq!(format!("{:?}", Duration::new(0, 999)), "999ns"); +} + +#[test] +fn debug_formatting_precision_zero() { + assert_eq!(format!("{:.0?}", Duration::new(0, 0)), "0ns"); + assert_eq!(format!("{:.0?}", Duration::new(0, 123)), "123ns"); + + assert_eq!(format!("{:.0?}", Duration::new(0, 1_001)), "1µs"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_999)), "1µs"); + + assert_eq!(format!("{:.0?}", Duration::new(0, 1_000_001)), "1ms"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_999_999)), "1ms"); + + assert_eq!(format!("{:.0?}", Duration::new(1, 000_000_001)), "1s"); + assert_eq!(format!("{:.0?}", Duration::new(1, 999_999_999)), "1s"); +} + +#[test] +fn debug_formatting_precision_two() { + // This might seem inconsistent with the other units, but printing + // fractional digits for nano seconds would imply more precision than is + // actually stored. + assert_eq!(format!("{:.2?}", Duration::new(0, 0)), "0ns"); + assert_eq!(format!("{:.2?}", Duration::new(0, 123)), "123ns"); + + assert_eq!(format!("{:.2?}", Duration::new(0, 1_000)), "1.00µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 7_001)), "7.00µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 7_100)), "7.10µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 1_999)), "1.99µs"); + + assert_eq!(format!("{:.2?}", Duration::new(0, 1_000_000)), "1.00ms"); + assert_eq!(format!("{:.2?}", Duration::new(0, 3_001_000)), "3.00ms"); + assert_eq!(format!("{:.2?}", Duration::new(0, 3_100_000)), "3.10ms"); + assert_eq!(format!("{:.2?}", Duration::new(0, 1_999_999)), "1.99ms"); + + assert_eq!(format!("{:.2?}", Duration::new(1, 000_000_000)), "1.00s"); + assert_eq!(format!("{:.2?}", Duration::new(4, 001_000_000)), "4.00s"); + assert_eq!(format!("{:.2?}", Duration::new(2, 100_000_000)), "2.10s"); + assert_eq!(format!("{:.2?}", Duration::new(8, 999_999_999)), "8.99s"); +} diff --git a/src/libcore/time.rs b/src/libcore/time.rs index 8e8b1691c657a..a0a48e8493ce3 100644 --- a/src/libcore/time.rs +++ b/src/libcore/time.rs @@ -21,6 +21,7 @@ //! assert_eq!(Duration::new(5, 0), Duration::from_secs(5)); //! ``` +use fmt; use iter::Sum; use ops::{Add, Sub, Mul, Div, AddAssign, SubAssign, MulAssign, DivAssign}; @@ -59,7 +60,7 @@ const MICROS_PER_SEC: u64 = 1_000_000; /// let ten_millis = Duration::from_millis(10); /// ``` #[stable(feature = "duration", since = "1.3.0")] -#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Debug, Hash, Default)] +#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Default)] pub struct Duration { secs: u64, nanos: u32, // Always 0 <= nanos < NANOS_PER_SEC @@ -481,3 +482,78 @@ impl<'a> Sum<&'a Duration> for Duration { iter.fold(Duration::new(0, 0), |a, b| a + *b) } } + +#[stable(feature = "duration_debug_impl", since = "1.27.0")] +impl fmt::Debug for Duration { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + /// Formats a floating point number in decimal notation. + /// + /// The number is given as the `integer_part` and a fractional part. + /// The value of the fractional part is `fractional_part / divisor`. So + /// `integer_part` = 3, `fractional_part` = 12 and `divisor` = 100 + /// represents the number `3.012`. Trailing zeros are omitted. + /// + /// `divisor` must not be above 100_000_000. It also should be a power + /// of 10, everything else doesn't make sense. `fractional_part` has + /// to be less than `10 * divisor`! + fn fmt_decimal( + f: &mut fmt::Formatter, + integer_part: u64, + mut fractional_part: u32, + mut divisor: u32, + ) -> fmt::Result { + // Encode the fractional part into a temporary buffer. The buffer + // only need to hold 9 elements, because `fractional_part` has to + // be smaller than 10^9. The buffer is prefilled with '0' digits + // to simplify the code below. + let mut buf = [b'0'; 9]; + + // The next digit is written at this position + let mut pos = 0; + + // We can stop when there are no non-zero digits left or (when a + // precision was set and we already emitted that many digits). + while fractional_part > 0 && f.precision().map(|p| p > pos).unwrap_or(true) { + // Write new digit into the buffer + buf[pos] = b'0' + (fractional_part / divisor) as u8; + + fractional_part %= divisor; + divisor /= 10; + pos += 1; + } + + // If we haven't emitted a single fractional digit and the precision + // wasn't set to a non-zero value, we don't print the decimal point. + let end = f.precision().unwrap_or(pos); + if end == 0 { + write!(f, "{}", integer_part) + } else { + // We are only writing ASCII digits into the buffer and it was + // initialized with '0's, so it contains valid UTF8. + let s = unsafe { + ::str::from_utf8_unchecked(&buf[..end]) + }; + + write!(f, "{}.{}", integer_part, s) + } + } + + // Print leading '+' sign if requested + if f.sign_plus() { + write!(f, "+")?; + } + + if self.secs > 0 { + fmt_decimal(f, self.secs, self.nanos, 100_000_000)?; + f.write_str("s") + } else if self.nanos >= 1_000_000 { + fmt_decimal(f, self.nanos as u64 / 1_000_000, self.nanos % 1_000_000, 100_000)?; + f.write_str("ms") + } else if self.nanos >= 1_000 { + fmt_decimal(f, self.nanos as u64 / 1_000, self.nanos % 1_000, 100)?; + f.write_str("µs") + } else { + write!(f, "{}ns", self.nanos) + } + } +} From 2a28ac31e9abe0a01861bfffed85872431cc6b72 Mon Sep 17 00:00:00 2001 From: Lukas Kalbertodt Date: Wed, 16 May 2018 14:46:37 +0200 Subject: [PATCH 2/3] Implement rounding for `Duration`s Debug output Rounding is done like for printing floating point numbers. If the first digit which isn't printed (due to the precision parameter) is larger than '4', the number is rounded up. --- src/libcore/tests/time.rs | 22 ++++++++++++++++------ src/libcore/time.rs | 36 +++++++++++++++++++++++++++++++++++- 2 files changed, 51 insertions(+), 7 deletions(-) diff --git a/src/libcore/tests/time.rs b/src/libcore/tests/time.rs index bfb5369cf8f8c..b0abdc749f69d 100644 --- a/src/libcore/tests/time.rs +++ b/src/libcore/tests/time.rs @@ -202,13 +202,19 @@ fn debug_formatting_precision_zero() { assert_eq!(format!("{:.0?}", Duration::new(0, 123)), "123ns"); assert_eq!(format!("{:.0?}", Duration::new(0, 1_001)), "1µs"); - assert_eq!(format!("{:.0?}", Duration::new(0, 1_999)), "1µs"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_499)), "1µs"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_500)), "2µs"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_999)), "2µs"); assert_eq!(format!("{:.0?}", Duration::new(0, 1_000_001)), "1ms"); - assert_eq!(format!("{:.0?}", Duration::new(0, 1_999_999)), "1ms"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_499_999)), "1ms"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_500_000)), "2ms"); + assert_eq!(format!("{:.0?}", Duration::new(0, 1_999_999)), "2ms"); assert_eq!(format!("{:.0?}", Duration::new(1, 000_000_001)), "1s"); - assert_eq!(format!("{:.0?}", Duration::new(1, 999_999_999)), "1s"); + assert_eq!(format!("{:.0?}", Duration::new(1, 499_999_999)), "1s"); + assert_eq!(format!("{:.0?}", Duration::new(1, 500_000_000)), "2s"); + assert_eq!(format!("{:.0?}", Duration::new(1, 999_999_999)), "2s"); } #[test] @@ -222,15 +228,19 @@ fn debug_formatting_precision_two() { assert_eq!(format!("{:.2?}", Duration::new(0, 1_000)), "1.00µs"); assert_eq!(format!("{:.2?}", Duration::new(0, 7_001)), "7.00µs"); assert_eq!(format!("{:.2?}", Duration::new(0, 7_100)), "7.10µs"); - assert_eq!(format!("{:.2?}", Duration::new(0, 1_999)), "1.99µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 7_109)), "7.11µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 7_199)), "7.20µs"); + assert_eq!(format!("{:.2?}", Duration::new(0, 1_999)), "2.00µs"); assert_eq!(format!("{:.2?}", Duration::new(0, 1_000_000)), "1.00ms"); assert_eq!(format!("{:.2?}", Duration::new(0, 3_001_000)), "3.00ms"); assert_eq!(format!("{:.2?}", Duration::new(0, 3_100_000)), "3.10ms"); - assert_eq!(format!("{:.2?}", Duration::new(0, 1_999_999)), "1.99ms"); + assert_eq!(format!("{:.2?}", Duration::new(0, 1_999_999)), "2.00ms"); assert_eq!(format!("{:.2?}", Duration::new(1, 000_000_000)), "1.00s"); assert_eq!(format!("{:.2?}", Duration::new(4, 001_000_000)), "4.00s"); assert_eq!(format!("{:.2?}", Duration::new(2, 100_000_000)), "2.10s"); - assert_eq!(format!("{:.2?}", Duration::new(8, 999_999_999)), "8.99s"); + assert_eq!(format!("{:.2?}", Duration::new(2, 104_990_000)), "2.10s"); + assert_eq!(format!("{:.2?}", Duration::new(2, 105_000_000)), "2.11s"); + assert_eq!(format!("{:.2?}", Duration::new(8, 999_999_999)), "9.00s"); } diff --git a/src/libcore/time.rs b/src/libcore/time.rs index a0a48e8493ce3..34bf3637f298f 100644 --- a/src/libcore/time.rs +++ b/src/libcore/time.rs @@ -498,7 +498,7 @@ impl fmt::Debug for Duration { /// to be less than `10 * divisor`! fn fmt_decimal( f: &mut fmt::Formatter, - integer_part: u64, + mut integer_part: u64, mut fractional_part: u32, mut divisor: u32, ) -> fmt::Result { @@ -522,6 +522,40 @@ impl fmt::Debug for Duration { pos += 1; } + // If a precision < 9 was specified, there may be some non-zero + // digits left that weren't written into the buffer. In that case we + // need to perform rounding to match the semantics of printing + // normal floating point numbers. However, we only need to do work + // when rounding up. This happens if the first digit of the + // remaining ones is >= 5. + if fractional_part > 0 && fractional_part >= divisor * 5 { + // Round up the number contained in the buffer. We go through + // the buffer backwards and keep track of the carry. + let mut rev_pos = pos; + let mut carry = true; + while carry && rev_pos > 0 { + rev_pos -= 1; + + // If the digit in the buffer is not '9', we just need to + // increment it and can stop then (since we don't have a + // carry anymore). Otherwise, we set it to '0' (overflow) + // and continue. + if buf[rev_pos] < b'9' { + buf[rev_pos] += 1; + carry = false; + } else { + buf[rev_pos] = b'0'; + } + } + + // If we still have the carry bit set, that means that we set + // the whole buffer to '0's and need to increment the integer + // part. + if carry { + integer_part += 1; + } + } + // If we haven't emitted a single fractional digit and the precision // wasn't set to a non-zero value, we don't print the decimal point. let end = f.precision().unwrap_or(pos); From 59e71141029162fe4b4a3ed4cad430dace3fb995 Mon Sep 17 00:00:00 2001 From: Lukas Kalbertodt Date: Wed, 16 May 2018 15:08:39 +0200 Subject: [PATCH 3/3] Fix `Debug` impl of `Duration` for precisions > 9 Previously, the code would panic for high precision values. Now it has the same behavior as printing normal floating point values: if a high precision is specified, '0's are added. --- src/libcore/tests/time.rs | 16 +++++++++++----- src/libcore/time.rs | 19 +++++++++++++------ 2 files changed, 24 insertions(+), 11 deletions(-) diff --git a/src/libcore/tests/time.rs b/src/libcore/tests/time.rs index b0abdc749f69d..ef3e1acfbf502 100644 --- a/src/libcore/tests/time.rs +++ b/src/libcore/tests/time.rs @@ -219,11 +219,8 @@ fn debug_formatting_precision_zero() { #[test] fn debug_formatting_precision_two() { - // This might seem inconsistent with the other units, but printing - // fractional digits for nano seconds would imply more precision than is - // actually stored. - assert_eq!(format!("{:.2?}", Duration::new(0, 0)), "0ns"); - assert_eq!(format!("{:.2?}", Duration::new(0, 123)), "123ns"); + assert_eq!(format!("{:.2?}", Duration::new(0, 0)), "0.00ns"); + assert_eq!(format!("{:.2?}", Duration::new(0, 123)), "123.00ns"); assert_eq!(format!("{:.2?}", Duration::new(0, 1_000)), "1.00µs"); assert_eq!(format!("{:.2?}", Duration::new(0, 7_001)), "7.00µs"); @@ -244,3 +241,12 @@ fn debug_formatting_precision_two() { assert_eq!(format!("{:.2?}", Duration::new(2, 105_000_000)), "2.11s"); assert_eq!(format!("{:.2?}", Duration::new(8, 999_999_999)), "9.00s"); } + +#[test] +fn debug_formatting_precision_high() { + assert_eq!(format!("{:.5?}", Duration::new(0, 23_678)), "23.67800µs"); + + assert_eq!(format!("{:.9?}", Duration::new(1, 000_000_000)), "1.000000000s"); + assert_eq!(format!("{:.10?}", Duration::new(4, 001_000_000)), "4.0010000000s"); + assert_eq!(format!("{:.20?}", Duration::new(4, 001_000_000)), "4.00100000000000000000s"); +} diff --git a/src/libcore/time.rs b/src/libcore/time.rs index 34bf3637f298f..9703c61fe92a1 100644 --- a/src/libcore/time.rs +++ b/src/libcore/time.rs @@ -511,9 +511,9 @@ impl fmt::Debug for Duration { // The next digit is written at this position let mut pos = 0; - // We can stop when there are no non-zero digits left or (when a - // precision was set and we already emitted that many digits). - while fractional_part > 0 && f.precision().map(|p| p > pos).unwrap_or(true) { + // We keep writing digits into the buffer while there are non-zero + // digits left and we haven't written enough digits yet. + while fractional_part > 0 && pos < f.precision().unwrap_or(9) { // Write new digit into the buffer buf[pos] = b'0' + (fractional_part / divisor) as u8; @@ -556,9 +556,13 @@ impl fmt::Debug for Duration { } } + // Determine the end of the buffer: if precision is set, we just + // use as many digits from the buffer (capped to 9). If it isn't + // set, we only use all digits up to the last non-zero one. + let end = f.precision().map(|p| ::cmp::min(p, 9)).unwrap_or(pos); + // If we haven't emitted a single fractional digit and the precision // wasn't set to a non-zero value, we don't print the decimal point. - let end = f.precision().unwrap_or(pos); if end == 0 { write!(f, "{}", integer_part) } else { @@ -568,7 +572,9 @@ impl fmt::Debug for Duration { ::str::from_utf8_unchecked(&buf[..end]) }; - write!(f, "{}.{}", integer_part, s) + // If the user request a precision > 9, we pad '0's at the end. + let w = f.precision().unwrap_or(pos); + write!(f, "{}.{:0