Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve Debug impl of time::Duration #50364

Merged
merged 3 commits into from
May 26, 2018

Conversation

LukasKalbertodt
Copy link
Member

@LukasKalbertodt LukasKalbertodt commented May 1, 2018

Hi there!

For a long time now, I was getting annoyed by the derived Debug impl of Duration. Usually, I use Duration to either do quick'n'dirty benchmarking or measuring the time of some operation in general. The output of the derived Debug impl is hard to parse for humans: is { secs: 0, nanos: 968360102 } or { secs: 0, nanos 98507324 } longer?

So after running into the annoyance several times (sometimes building my own function to print the Duration properly), I decided to tackle this. Now the output looks like this:

Duration::new(1, 0)                 => 1s
Duration::new(1, 1)                 => 1.000000001s
Duration::new(1, 300)               => 1.0000003s
Duration::new(1, 4000)              => 1.000004s
Duration::new(1, 600000)            => 1.0006s
Duration::new(1, 7000000)           => 1.007s
Duration::new(0, 0)                 => 0ns
Duration::new(0, 1)                 => 1ns
Duration::new(0, 300)               => 300ns
Duration::new(0, 4001)              => 4.001µs
Duration::new(0, 600300)            => 600.3µs
Duration::new(0, 7000000)           => 7ms

Note that I implemented the formatting manually and didn't use floats. No information is "lost" when printing. So Duration::new(123_456_789_000, 900_000_001) prints as 123456789000.900000001s.

This is not yet finished, but I wanted to open the PR now already in order to get some feedback (maybe everyone likes the derived impl).

Still ToDo:

  • Respect precision and width parameter of the formatter (see this comment)

Alternatives/Decisions

  • Should large durations displayed in minutes, hours, days, ...? For now, I decided not to because the current formatting is close the how a Duration is stored. From this new Debug output, you can still easily see what the values of secs and nanos are. A formatting like 3h 27m 12s 9ms might be more appropriate for a Display impl?
  • Should this rather be a Display impl and should Debug be derived? Maybe this formatting is too fancy for Debug? In my opinion it's not and, as already mentioned, from the current format one can still very easily determine the values for secs and nanos.
  • Whitespace between the number and the unit?

Notes for reviewers

  • The combined diff sucks. Rather review both commits individually.
  • In the unit test, I am building my own type implementing fmt::Write to test the output. Maybe there is already something like that which I can use?
  • My Debug impl block is marked as #[stable(...)]... but that's fine since the derived Debug impl was stable already, right?

Apart from the main change, I moved all time unit tests into the tests directory. All other libcore tests are there, so I guess it was simply an oversight. Prior to this change, the time tests weren't run, so I guess this is kind of a bug fix. If my Debug impl is rejected, I can of course just send the fix as PR. (this was already merged in #50466)

@rust-highfive
Copy link
Collaborator

r? @KodrAus

(rust_highfive has picked a reviewer for you, use r? to override)

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label May 1, 2018
@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-3.9 of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.

[00:04:39] travis_fold:start:tidy
travis_time:start:tidy
tidy check
[00:04:40] tidy error: /checkout/src/libcore/tests/time.rs: incorrect license
[00:04:41] some tidy checks failed
[00:04:41] 
[00:04:41] 
[00:04:41] command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0-tools-bin/tidy" "/checkout/src" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "--no-vendor" "--quiet"
[00:04:41] 
[00:04:41] 
[00:04:41] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test src/tools/tidy
[00:04:41] Build completed unsuccessfully in 0:01:46
[00:04:41] Build completed unsuccessfully in 0:01:46
[00:04:41] make: *** [tidy] Error 1
[00:04:41] Makefile:79: recipe for target 'tidy' failed

The command "stamp sh -x -c "$RUN_SCRIPT"" exited with 2.
travis_time:start:09f752a4
$ date && (curl -fs --head https://google.com | grep ^Date: | sed 's/Date: //g' || true)

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@LukasKalbertodt LukasKalbertodt changed the title WIP: Improve Debug imps of time::Duration WIP: Improve Debug impl of time::Duration May 1, 2018
@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-3.9 of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
[01:07:40] travis_fold:start:test_stage1-core
travis_time:start:test_stage1-core
Testing core stage1 (x86_64-unknown-linux-gnu -> x86_64-unknown-linux-gnu)
[01:07:40]    Compiling core v0.0.0 (file:///checkout/src/libcore)
unwind jemalloc backtrace" "--manifest-path" "/checkout/src/libstd/Cargo.toml" "-p" "core" "--" "--quiet"
[01:08:07] 
[01:08:07] 
[01:08:07] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test
[01:08:07] Build completed unsuccessfully in 0:28:20
[01:08:07] Build completed unsuccessfully in 0:28:20
[01:08:07] Makefile:58: recipe for target 'check' failed
[01:08:07] make: *** [check] Error 1

The command "stamp sh -x -c "$RUN_SCRIPT"" exited with 2.
travis_time:start:00fefb50
$ date && (curl -fs --head https://google.com | grep ^Date: | sed 's/Date: //g' || true)

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@LukasKalbertodt
Copy link
Member Author

Failure caused by warnings in some of the tests I moved. So yeah, apparently those tests weren't executed in quite some time...

Hopefully those tests are fixed now.

@LukasKalbertodt
Copy link
Member Author

LukasKalbertodt commented May 2, 2018

I checked the different formatting options that this impl could respect, but I concluded that most are not worth it. When was the last time you specified any formatting options while using ? for debug output? I think I never did...

  • The whole fill/alignment/padding is pretty hard to implement (especially since this is in core and can't allocate) and I doubt that anyone would use that anyway. Additionally, even the fmt docs say: "Note that alignment may not be implemented by some types. A good way to ensure padding is applied is to format your input, then use this resulting string to pad your output."
  • The alternate flag # is not really applicable here: it doesn't make sense to switch to pretty printing again
  • The precision is a bit problematic. That's because the current impl switches between units depending on the value. What should {:.2?} mean? Always show two digits after the decimal point (2.14s but also 930.01µs)? Or: show no values less than 1/100th of a second. I don't like either of those, but maybe the first makes more sense. I can implement it, if anyone thinks it's useful. (I changed my mind)

So, I just implemented the + flag now and will remove the "WIP" status as I think this PR is ready and needs feedback to continue.

@LukasKalbertodt LukasKalbertodt changed the title WIP: Improve Debug impl of time::Duration Improve Debug impl of time::Duration May 2, 2018
@kennytm kennytm added the T-libs-api Relevant to the library API team, which will review and decide on the PR/issue. label May 4, 2018
@bors
Copy link
Contributor

bors commented May 6, 2018

☔ The latest upstream changes (presumably #50466) made this pull request unmergeable. Please resolve the merge conflicts.

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
@LukasKalbertodt
Copy link
Member Author

  • Rebased
  • The code is a bit shorter now
  • Respect the precision parameter of the formatter (I changed my mind and think it does make sense...)
  • I noticed that I can use format!() in tests, so I removed my dirty hack from before
  • I added more unit tests and split test cases in multiple test functions

Should be ready now ^_^

@Stargateur
Copy link
Contributor

I would like to do a critic about this feature:

  1. Is this really a Debug output ? If we want to debug Duration, we will want to know the exact values of secs and nanos. With this feature, I need to "reverse" the result myself.
  2. Debug implementation should be as simple as possible, your implementation is a little bit complicated for me. That make that if we want debug Duration we can't know if it's Debug that bug or something else in Duration.

I see two solution to my concern:

  1. Should we just change your Debug implementation to a Display implementation ? This look logical to me but I don't know if this do a breaking change.
  2. If not we could add the real value in your actual output something like 1s (1s, 0n), 1.000004s (1s, 4000) or 4.001µs (0s, 4001n)

@LukasKalbertodt
Copy link
Member Author

LukasKalbertodt commented May 7, 2018

Summary: I don't quite care whether or not this becomes a Debug or Display impl. However, I think a Display impl could lead to long discussions about "the right default way to format". And I think my impl is not "incorrect" for the Debug trait and is fine the way it is.


My reasoning for implementing Debug was:

I assumed the Display trait is implemented only if there is one clear default way to represent that value as a string. For duration, I don't think everyone would agree on one default way (e.g. "should we print hours and minutes?"). The fmt docs state:

fmt::Display implementations assert that the type can be faithfully represented as a UTF-8 string at all times. It is not expected that all types implement the Display trait.

Display is similar to Debug, but Display is for user-facing output, and so cannot be derived.

This requirement doesn't sound too strict. However, it's still not clear what "user-facing output" for Duration should look like.

About Debug, the docs say "Output will typically represent the internal state as faithfully as possible." Note that it says "faithfully" but not "explicitly". In my opinion, my implementation does represent the internals faithfully, because it never omits information. Yes, figuring out the number of nano seconds requires some thinking, but not a lot (everything is just a base 10 off).

There are a number of other Debug impls which are also neither "easy" nor "explicit":

  • str: some chars are escaped, but absolutely not all. So one could also argue that the programmer want's to see the raw bytes for debugging purposes. Also: length is now implicit.
  • Collections, such as Vec<T>: Only the elements are printed, which means:
    • The length of the collection is implicit (you'd have to count)
    • The capacity of the collection is completely omitted

So Debug impls may in fact be non-trivial, making explicit information implicit, and apparently even hiding information if it's not important for most users. And as a user: how often are you really interested in the exact values of secs and nanos in the explicit representation? I never was...

@Stargateur
Copy link
Contributor

Stargateur commented May 7, 2018

You said

The output of the derived Debug impl is hard to parse for humans: is { secs: 0, nanos: 968360102 } or { secs: 0, nanos 98507324 } longer?

I could answer you with your own sentence (just need to inverse it):

Yes, figuring out the number of nano seconds requires some thinking, but not a lot (everything is just a base 10 off).


Output will typically represent the internal state as faithfully as possible.

I agree with you about "faithfully" but the sentence clearly say "as possible". I think it's possible to be more accurate about the internal state of Duration than your new implementation as I show it in my previous exemple 1s (1s, 0n).

And your exemple with Collection and str, are a very strong argument but maybe they are wrong to do that ? I'm not a experimented rust user, so maybe this has been discute before, but in my opinion, I don't see why Collection and str don't print their length and their capacity.

I assumed the Display trait is implemented only if there is one clear default way to represent that value as a string.
And as a user: how often are you really interested in the exact values of secs and nanos in the explicit representation? I never was...

I really like your output as a user of Duration, this is why I propose Display because I think Duration is only use and read by the programmer so Display a Duration could be considerate as a the programmer user ? If I want something standard and the represent time that I want to print to a final user (anyone), I will use Chrono. And as the documentation of Duration clearly state, "Each Duration is composed of a whole number of seconds and a fractional part represented in nanoseconds." so I think it's logical to print it like you do for a Display trait, no need for minute or hour. And maybe we could just agree about one way to represent Duration and starting to call it the standard way ;) ?

Your new implementation look nice enough for me to be a good candidate to Display it. But again all of this is just my little opinion, I would be happy even with your current proposition because I think it's a good improvement.

@KodrAus
Copy link
Contributor

KodrAus commented May 9, 2018

I'll dig into the source shortly, but just thought I'd leave a note now to say I'm in favour of this clearer Debug implementation. Representing values as pseudo structures in Debug is a good default that can always be derived, but when we can do better I think we should 👍

@pietroalbini
Copy link
Member

Ping from triage @KodrAus! You need to complete your review!

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");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, the precision here is a bit inconsistent with floating points, that will also perform rounding through its unholy rendering machinery. For instance:

assert_eq!("2.00", format!("{:.2}", 1.995f32));

We might want to consider rounding here too.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point! I just pushed a commit which adds correct rounding like floats do. I also pushed a commit which fixes the behavior for a precision > 9.

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.
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.
@pietroalbini
Copy link
Member

Can we get a crater run for this? Last time we changed the debug output there were some regressions (some crates assumes the debug output is guaranteed not to change, it would be nice to alert the authors).

@pietroalbini
Copy link
Member

cc @rust-lang/infra

@kennytm
Copy link
Member

kennytm commented May 16, 2018

@bors try

@bors
Copy link
Contributor

bors commented May 16, 2018

⌛ Trying commit 59e7114 with merge 68967b5e9d4ec8c0ad4f402e6bf624995b499cdf...

@kennytm kennytm added the S-waiting-on-crater Status: Waiting on a crater run to be completed. label May 16, 2018
@Mark-Simulacrum
Copy link
Member

Crater started.

@pietroalbini pietroalbini removed the S-waiting-on-crater Status: Waiting on a crater run to be completed. label May 21, 2018
@pietroalbini
Copy link
Member

Hi myself and @KodrAus! Crater results are at: http://cargobomb-reports.s3.amazonaws.com/pr-50364/index.html. 'Blacklisted' crates (spurious failures etc) can be found here. If you see any spurious failures not on the list, please make a PR against that file.

(interested observers: Crater is a tool for testing the impact of changes on the crates.io ecosystem. You can find out more at the repo if you're curious)

@LukasKalbertodt
Copy link
Member Author

I quickly scanned the crater results and none of the 7 regressions look like they are caused by this change.

@KodrAus
Copy link
Contributor

KodrAus commented May 26, 2018

This looks good to me!

@bors r+

@bors
Copy link
Contributor

bors commented May 26, 2018

📌 Commit 59e7114 has been approved by KodrAus

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels May 26, 2018
@KodrAus
Copy link
Contributor

KodrAus commented May 26, 2018

Thanks again for working on this @LukasKalbertodt!

@bors
Copy link
Contributor

bors commented May 26, 2018

⌛ Testing commit 59e7114 with merge 85e8e0f19506d467f478c8d2f66f508de021e4db...

@bors
Copy link
Contributor

bors commented May 26, 2018

💔 Test failed - status-travis

@bors bors added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels May 26, 2018
@rust-highfive
Copy link
Collaborator

The job dist-armhf-linux of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
  0     0    0     0    0     0      0      0 --:--:--  0:00:15 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:16 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:17 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:18 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:19 --:--:--     0curl: (6) Could not resolve host: s3-us-west-1.amazonaws.com
[01:10:10] thread 'main' panicked at 'failed to download openssl source: exit code: 6', bootstrap/native.rs:575:17
[01:10:10] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap dist --host arm-unknown-linux-gnueabihf --target arm-unknown-linux-gnueabihf
[01:10:10] Build completed unsuccessfully in 1:07:15
travis_time:end:362f4f7c:start=1527312208144659736,finish=1527316419097934427,duration=4210953274691

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

1 similar comment
@rust-highfive
Copy link
Collaborator

The job dist-armhf-linux of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
  0     0    0     0    0     0      0      0 --:--:--  0:00:15 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:16 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:17 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:18 --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:19 --:--:--     0curl: (6) Could not resolve host: s3-us-west-1.amazonaws.com
[01:10:10] thread 'main' panicked at 'failed to download openssl source: exit code: 6', bootstrap/native.rs:575:17
[01:10:10] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap dist --host arm-unknown-linux-gnueabihf --target arm-unknown-linux-gnueabihf
[01:10:10] Build completed unsuccessfully in 1:07:15
travis_time:end:362f4f7c:start=1527312208144659736,finish=1527316419097934427,duration=4210953274691

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@pietroalbini
Copy link
Member

pietroalbini commented May 26, 2018

Failure to resove dns names #40474.

@bors retry

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels May 26, 2018
@bors
Copy link
Contributor

bors commented May 26, 2018

⌛ Testing commit 59e7114 with merge 8d7c0ed49df2d0deabe6e737f4ffdaefd5ed983b...

@bors
Copy link
Contributor

bors commented May 26, 2018

⌛ Testing commit 59e7114 with merge 444a9c3...

bors added a commit that referenced this pull request May 26, 2018
…=KodrAus

Improve `Debug` impl of `time::Duration`

Hi there!

For a long time now, I was getting annoyed by the derived `Debug` impl of `Duration`. Usually, I use `Duration` to either do quick'n'dirty benchmarking or measuring the time of some operation in general. The output of the derived Debug impl is hard to parse for humans: is { secs: 0, nanos: 968360102 } or { secs: 0, nanos 98507324 } longer?

So after running into the annoyance several times (sometimes building my own function to print the Duration properly), I decided to tackle this. Now the output looks like this:

```
Duration::new(1, 0)                 => 1s
Duration::new(1, 1)                 => 1.000000001s
Duration::new(1, 300)               => 1.0000003s
Duration::new(1, 4000)              => 1.000004s
Duration::new(1, 600000)            => 1.0006s
Duration::new(1, 7000000)           => 1.007s
Duration::new(0, 0)                 => 0ns
Duration::new(0, 1)                 => 1ns
Duration::new(0, 300)               => 300ns
Duration::new(0, 4001)              => 4.001µs
Duration::new(0, 600300)            => 600.3µs
Duration::new(0, 7000000)           => 7ms
```

Note that I implemented the formatting manually and didn't use floats. No information is "lost" when printing. So `Duration::new(123_456_789_000, 900_000_001)` prints as `123456789000.900000001s`.

~~This is not yet finished~~, but I wanted to open the PR now already in order to get some feedback (maybe everyone likes the derived impl).

### Still ToDo:

- [x] Respect precision ~~and width~~ parameter of the formatter (see [this comment](#50364 (comment)))

### Alternatives/Decisions

- Should large durations displayed in minutes, hours, days, ...? For now, I decided not to because the current formatting is close the how a `Duration` is stored. From this new `Debug` output, you can still easily see what the values of `secs` and `nanos` are. A formatting like `3h 27m 12s 9ms` might be more appropriate for a `Display` impl?
- Should this rather be a `Display` impl and should `Debug` be derived? Maybe this formatting is too fancy for `Debug`? In my opinion it's not and, as already mentioned, from the current format one can still very easily determine the values for `secs` and `nanos`.
- Whitespace between the number and the unit?

### Notes for reviewers

- ~~The combined diff sucks. Rather review both commits individually.~~
- ~~In the unit test, I am building my own type implementing `fmt::Write` to test the output. Maybe there is already something like that which I can use?~~
- My `Debug` impl block is marked as `#[stable(...)]`... but that's fine since the derived Debug impl was stable already, right?

---

~~Apart from the main change, I moved all `time` unit tests into the `tests` directory. All other `libcore` tests are there, so I guess it was simply an oversight. Prior to this change, the `time` tests weren't run, so I guess this is kind of a bug fix. If my `Debug` impl is rejected, I can of course just send the fix as PR.~~ (this was already merged in #50466)
@bors
Copy link
Contributor

bors commented May 26, 2018

☀️ Test successful - status-appveyor, status-travis
Approved by: KodrAus
Pushing 444a9c3 to master...

@bors bors merged commit 59e7114 into rust-lang:master May 26, 2018
@pietroalbini pietroalbini added the relnotes Marks issues that should be documented in the release notes of the next release. label May 26, 2018
@scottmcm
Copy link
Member

scottmcm commented Jun 1, 2018

Thanks for including precision! For a real duration, I'd always rather 1.00s over 1.000000001s.

@uberjay
Copy link

uberjay commented Aug 2, 2018

Thank you for this! It's always nice when updating my compiler gives me prettier debug logging for free!

@LukasKalbertodt LukasKalbertodt deleted the improve-duration-debug-impl branch May 3, 2020 16:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
relnotes Marks issues that should be documented in the release notes of the next release. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. T-libs-api Relevant to the library API team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.