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

Enhance report-time option #64873

Merged
merged 7 commits into from
Oct 13, 2019
Merged

Enhance report-time option #64873

merged 7 commits into from
Oct 13, 2019

Conversation

popzxc
Copy link
Contributor

@popzxc popzxc commented Sep 28, 2019

Short overview

This PR is a follow-up to a previously closed #64714 PR.

Changes introduced by this PR

  • libtest now retrieves the type of the test within TestDesc (available types are: UnitTest, IntegrationTest, DocTest, Unknown).
  • --report-time subcommand of the libtest now supports colored output (disabled by default).
  • Colorized output depends on the threshold values. Default values (proposed by @wesleywiser):
    • For unit-tests: 50ms warn/100ms critical,
    • For integration-tests: 500ms warn/1000ms critical,
    • For doctests: same as for integration tests,
    • For unknown tests: TEST_WARN_TIMEOUT_S warn/ TEST_WARN_TIMEOUT_S * 2 critical (it will only applied single-threaded mode, because otherwise test will be interrupted after reaching TEST_WARN_TIMEOUT_S).
    • These values can be overrided by setting environment variables (since those thresholds are somewhat constant for every project, it's more flexible to use environment variables than command line arguments).
  • New optional flag --ensure-test-time for libtest. With this flag applied, exectuion time limit excesss will cause test failure.

What have not been done

There was a comment that it would be nice to have an entry in the Cargo book about it.

However, changes introduced by this PR (and #64663 in which report-time flag was added) aren't related directly to cargo, it's more about libtest itself.
I'm considering that The Unstable Book is more appropriate place, but not sure if I'm right (and if so, how exactly it should be described).

As one possible option, this PR may be merged without denoting it in the documentation, and in the next PR adding support of this feature to the cargo itself, I'll add a note in the Cargo book.

Scope of this PR

Logical scope of this PR is libtest only. However, to get test types, I had to modify also libsyntax_ext and librustdoc for them to provide information about test type.

Rationale

Rationale for colored output was submitted in #64714

Providing the information about kind of test was also proposed in #64714, and as an additional benefit this information may be useful for the tools using libtest (e.g. cargo).

Adding flag to treat time limits excess seems logical to me, so projects that do care about test execution time won't have to invent a wheel.

Backward compatibility

All the changes are completely backward compatible.

Demo

rustc_enhanced_time

r? @wesleywiser

@JohnTitor JohnTitor added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Sep 28, 2019
Copy link
Member

@wesleywiser wesleywiser left a comment

Choose a reason for hiding this comment

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

Overall, this looks really good! If you think the unstable book makes more sense than the cargo book, that's fine with me. I just want to make sure there's documentation somewhere but it doesn't matter too much where.

@wesleywiser
Copy link
Member

cc @Centril in case they had any feedback. Otherwise I'll r+ tomorrow.

src/libtest/lib.rs Show resolved Hide resolved
src/libtest/lib.rs Show resolved Hide resolved
src/libtest/lib.rs Show resolved Hide resolved
src/libtest/lib.rs Show resolved Hide resolved
@@ -601,6 +802,19 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
};
}

let report_time = unstable_optflag!(matches, allow_unstable, "report-time");
Copy link
Contributor

Choose a reason for hiding this comment

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

This part from let report_time until else { None }; can be extracted into a function.

@@ -76,13 +77,54 @@ mod tests;
const TEST_WARN_TIMEOUT_S: u64 = 60;
const QUIET_MODE_MAX_COLUMN: usize = 100; // insert a '\n' after 100 tests in quiet mode

/// This small module contains constants used by `report-time` option.
Copy link
Contributor

Choose a reason for hiding this comment

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

The file is pretty large already (2kloc) so it would be good to add the new related changes into a dedicated file.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I agree, but I think it will be better to not only move new changes into new file, but refactor the whole file and create several logically-consistent files (e.g. cli.rs, time_options.rs, benches.rs, etc).
I'm going to do that in the next PR. Will it be OK?

Copy link
Contributor

Choose a reason for hiding this comment

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

I'm going to do that in the next PR. Will it be OK?

Sure, that sounds great!

@Centril
Copy link
Contributor

Centril commented Sep 28, 2019

  • For unit-tests: 50ms warn/100ms critical,

How does this fit with e.g. https://github.com/altsysrq/proptest and quickcheck unit tests...? 🤔
cc @Eh2406 @ehuss @AltSysrq @BurntSushi

@popzxc
Copy link
Contributor Author

popzxc commented Sep 29, 2019

@Centril regarding the 50ms/100ms threshold for unit test.

I've used the values proposed in the previous PR, and in general I agree that those values won't suit everyones needs.
That's exactly the reason why by default colored output is disabled and those values can be overrided.

As a follow-up, in the one of the next PRs I can make an additional section in cargo.toml, so users will be able to define the limits project-wise without dealing with different environment variables for every project (as I understand it, it's a common scenario.

@popzxc
Copy link
Contributor Author

popzxc commented Sep 29, 2019

Well, regarding the entry in the Unstable book.

I have done it locally, but tidy fails:

tidy error: The Unstable Book has a 'library feature' section 'libtest-report-time' which doesn't correspond to an unstable library feature
some tidy checks failed

I've opened a tracking issue: #64888, however, this check still fails.

Can somebody please guide me what exactly should I do here?

fn get_time_options(
matches: &getopts::Matches,
allow_unstable: bool)
-> Option<OptPartRes<TestTimeOptions>> {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Talking about quite over-complicated return type: as I mentioned before, I want to split libtest into several modules, so every module will be able to parse options of itself.
Thus, we will have a bunch of functions like get_XXX_options which will return Option<OptPartRes<T>>, and one master function in cli.rs which will combain options parts from different modules.

However, as I can see, currently None is returned only if help argument was passed, so I guess I'll be able to simplify signature to be just OptPartRes<T>.

@bors
Copy link
Contributor

bors commented Sep 29, 2019

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

TrBench(ref bs) => {
self.write_bench()?;
self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))
self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))?;
Copy link
Contributor

Choose a reason for hiding this comment

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

You added a \n after the match, so you can remove this one.

)
.optflag(
"",
"ensure-test-time",
Copy link
Contributor

Choose a reason for hiding this comment

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

This parameter name could be more consistent with report-time. Either

  • report-time and ensure-time or
  • report-test-time and ensure-test-time



// If test is already failed (or allowed to fail), do not change the result.
if result != TrOk {
Copy link
Contributor

Choose a reason for hiding this comment

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

I think you need to check result != TrOk && result != TrAllowedFail

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'm not sure. If test is allowed to fail, I think user will be confused if that test will anyway be failed in result.

Copy link
Contributor

Choose a reason for hiding this comment

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

I'm not sure about that, either. Probably it doesn't matter because this feature will be removed, #46488.

@popzxc
Copy link
Contributor Author

popzxc commented Oct 3, 2019

Regarding merge conflict: I will resolve it soon (as well as review comment).

However, I'm still waiting for any guidance for adding an entry to unstable book comment.

src/libtest/lib.rs Show resolved Hide resolved
src/libtest/lib.rs Show resolved Hide resolved
let time_options = match get_time_options(&matches, allow_unstable) {
Some(Ok(val)) => val,
Some(Err(e)) => return Some(Err(e)),
x => panic!("Unexpected output from `get_time_options`: {:?}", x),
Copy link
Contributor

Choose a reason for hiding this comment

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

Is x always None? Matching None explicitly makes it clearer.

Comment on lines +664 to +709
`RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION` and
`RUST_TEST_TIME_DOCTEST` environment variables.
Copy link
Contributor

Choose a reason for hiding this comment

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

Is there any message visible to the user explaining him that these environment variables contain the warn time and the critical time?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It will be in the unstable book (and I will add a link to the corresponding page in that message) when somebody will answer my question.

Comment on lines 675 to 677
Threshold values for this option can be configured via
`RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION` and
`RUST_TEST_TIME_DOCTEST` environment variables."
Copy link
Contributor

Choose a reason for hiding this comment

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

These environment variables take two numbers. Which number is the "test execution time limit"?

@wesleywiser
Copy link
Member

@Mark-Simulacrum do you know the correct way to resolve the tidy error in #64873 (comment)?

@Mark-Simulacrum
Copy link
Member

I don't see any changes to the unstable book in this PR, which would be helpful -- I don't think we auto generate it?

Initial suspicion is that you want underscores instead of dashes somewhere, though.

@popzxc
Copy link
Contributor Author

popzxc commented Oct 9, 2019

Well, I've resolved an merge confict issue and (hopefully) all the review comments.

r? @wesleywiser

@Mark-Simulacrum I've committed an entry that I have added to the unstable book, so I will be really gratefull, if you'll tell me what I should do to resolve tidy error.

@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-6.0 of your PR failed (pretty log, 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.
2019-10-09T07:04:28.8351442Z ##[command]git remote add origin https://github.com/rust-lang/rust
2019-10-09T07:04:28.8530364Z ##[command]git config gc.auto 0
2019-10-09T07:04:28.8599814Z ##[command]git config --get-all http.https://github.com/rust-lang/rust.extraheader
2019-10-09T07:04:28.8649215Z ##[command]git config --get-all http.proxy
2019-10-09T07:04:28.8784282Z ##[command]git -c http.extraheader="AUTHORIZATION: basic ***" fetch --force --tags --prune --progress --no-recurse-submodules --depth=2 origin +refs/heads/*:refs/remotes/origin/* +refs/pull/64873/merge:refs/remotes/pull/64873/merge
---
2019-10-09T07:11:29.0928449Z    Compiling serde_json v1.0.40
2019-10-09T07:11:30.9182156Z    Compiling tidy v0.1.0 (/checkout/src/tools/tidy)
2019-10-09T07:11:42.7204570Z     Finished release [optimized] target(s) in 1m 31s
2019-10-09T07:11:42.7286049Z tidy check
2019-10-09T07:11:43.3241384Z tidy error: /checkout/src/libtest/lib.rs:1766: line longer than 100 chars
2019-10-09T07:11:43.3241568Z tidy error: /checkout/src/libtest/lib.rs:1767: line longer than 100 chars
2019-10-09T07:11:44.1815939Z tidy error: The Unstable Book has a 'library feature' section 'report-time' which doesn't correspond to an unstable library feature
2019-10-09T07:11:44.8207425Z Found 478 error codes
2019-10-09T07:11:44.8207523Z Found 0 error codes with no tests
2019-10-09T07:11:44.8207566Z Done!
2019-10-09T07:11:44.8207628Z some tidy checks failed
2019-10-09T07:11:44.8207628Z some tidy checks failed
2019-10-09T07:11:44.8207658Z 
2019-10-09T07:11:44.8207717Z 
2019-10-09T07:11:44.8208732Z 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"
2019-10-09T07:11:44.8208860Z 
2019-10-09T07:11:44.8208886Z 
2019-10-09T07:11:44.8212448Z failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test src/tools/tidy
2019-10-09T07:11:44.8212544Z Build completed unsuccessfully in 0:01:34
2019-10-09T07:11:44.8212544Z Build completed unsuccessfully in 0:01:34
2019-10-09T07:11:44.8261523Z == clock drift check ==
2019-10-09T07:11:44.8298021Z   local time: Wed Oct  9 07:11:44 UTC 2019
2019-10-09T07:11:44.9679177Z   network time: Wed, 09 Oct 2019 07:11:44 GMT
2019-10-09T07:11:44.9683186Z == end clock drift check ==
2019-10-09T07:11:46.3279312Z ##[error]Bash exited with code '1'.
2019-10-09T07:11:46.3311907Z ##[section]Starting: Checkout
2019-10-09T07:11:46.3313718Z ==============================================================================
2019-10-09T07:11:46.3313791Z Task         : Get sources
2019-10-09T07:11:46.3313855Z Description  : Get sources from a repository. Supports Git, TfsVC, and SVN repositories.

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)

@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-6.0 of your PR failed (pretty log, 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.
2019-10-09T07:30:03.0162921Z ##[command]git remote add origin https://github.com/rust-lang/rust
2019-10-09T07:30:03.0362109Z ##[command]git config gc.auto 0
2019-10-09T07:30:03.0447037Z ##[command]git config --get-all http.https://github.com/rust-lang/rust.extraheader
2019-10-09T07:30:03.0507067Z ##[command]git config --get-all http.proxy
2019-10-09T07:30:03.0653061Z ##[command]git -c http.extraheader="AUTHORIZATION: basic ***" fetch --force --tags --prune --progress --no-recurse-submodules --depth=2 origin +refs/heads/*:refs/remotes/origin/* +refs/pull/64873/merge:refs/remotes/pull/64873/merge
---
2019-10-09T07:37:13.9115880Z tidy check
2019-10-09T07:37:14.7871207Z * 584 error codes
2019-10-09T07:37:14.7871339Z * highest error code: E0739
2019-10-09T07:37:15.1662688Z * 266 features
2019-10-09T07:37:15.4266120Z tidy error: The Unstable Book has a 'library feature' section 'report-time' which doesn't correspond to an unstable library feature
2019-10-09T07:37:16.0906742Z Found 482 error codes
2019-10-09T07:37:16.0906872Z Found 0 error codes with no tests
2019-10-09T07:37:16.0906922Z Done!
2019-10-09T07:37:16.0906968Z some tidy checks failed
2019-10-09T07:37:16.0906968Z some tidy checks failed
2019-10-09T07:37:16.0907021Z 
2019-10-09T07:37:16.0907051Z 
2019-10-09T07:37:16.0908036Z 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"
2019-10-09T07:37:16.0908497Z 
2019-10-09T07:37:16.0908544Z 
2019-10-09T07:37:16.0911949Z failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test src/tools/tidy
2019-10-09T07:37:16.0912054Z Build completed unsuccessfully in 0:01:32
2019-10-09T07:37:16.0912054Z Build completed unsuccessfully in 0:01:32
2019-10-09T07:37:16.0966556Z == clock drift check ==
2019-10-09T07:37:16.0985653Z   local time: Wed Oct  9 07:37:16 UTC 2019
2019-10-09T07:37:16.2585543Z   network time: Wed, 09 Oct 2019 07:37:16 GMT
2019-10-09T07:37:16.2585896Z == end clock drift check ==
2019-10-09T07:37:17.6502378Z ##[error]Bash exited with code '1'.
2019-10-09T07:37:17.6544575Z ##[section]Starting: Checkout
2019-10-09T07:37:17.6546504Z ==============================================================================
2019-10-09T07:37:17.6546564Z Task         : Get sources
2019-10-09T07:37:17.6546647Z Description  : Get sources from a repository. Supports Git, TfsVC, and SVN repositories.

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)

@Mark-Simulacrum
Copy link
Member

Ah. The feature you've added is not a library feature (as usage does not imply #![feature(...)] and some path). I would move the documentation to the "compiler flags" section -- which we should probably rename to just "flags", but I don't think that needs to happen in this PR necessarily.

@popzxc
Copy link
Contributor Author

popzxc commented Oct 12, 2019

@Centril @jakoschiko Are you OK with the current state of this PR?

@Centril
Copy link
Contributor

Centril commented Oct 12, 2019

Code seems pretty clean from my end. :)

@wesleywiser
Copy link
Member

@bors r+

@bors
Copy link
Contributor

bors commented Oct 12, 2019

📌 Commit 15f571b has been approved by wesleywiser

@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 Oct 12, 2019
@jakoschiko
Copy link
Contributor

The current state looks good.

@bors
Copy link
Contributor

bors commented Oct 12, 2019

⌛ Testing commit 15f571b with merge 80b861b...

bors added a commit that referenced this pull request Oct 12, 2019
Enhance report-time option

## Short overview

This PR is a follow-up to a previously closed #64714 PR.

## Changes introduced by this PR

* `libtest` now retrieves the type of the test within `TestDesc` (available types are: `UnitTest`, `IntegrationTest`, `DocTest`, `Unknown`).
* `--report-time` subcommand of the `libtest` now supports colored output (disabled by default).
* Colorized output depends on the threshold values. Default values (proposed by @wesleywiser):
  - For unit-tests: 50ms warn/100ms critical,
  - For integration-tests: 500ms warn/1000ms critical,
  - For doctests: same as for integration tests,
  - For unknown tests: `TEST_WARN_TIMEOUT_S` warn/ `TEST_WARN_TIMEOUT_S * 2` critical (it will only applied single-threaded mode, because otherwise test will be interrupted after reaching `TEST_WARN_TIMEOUT_S`).
  - These values can be overrided by setting environment variables (since those thresholds are somewhat constant for every project, it's more flexible to use environment variables than command line arguments).
* New optional flag `--ensure-test-time` for `libtest`. With this flag applied, exectuion time limit excesss will cause test failure.

## What have not been done

There was a comment that it would be nice to have an entry in the Cargo book about it.

However, changes introduced by this PR (and #64663 in which `report-time` flag was added) aren't related directly to `cargo`, it's more about `libtest` itself.
I'm considering that [The Unstable Book](https://doc.rust-lang.org/unstable-book/) is more appropriate place, but not sure if I'm right (and if so, how exactly it should be described).

As one possible option, this PR may be merged without denoting it in the documentation, and in the next PR adding support of this feature to the `cargo` itself, I'll add a note in the Cargo book.

## Scope of this PR

Logical scope of this PR is `libtest` only. However, to get test types, I had to modify also `libsyntax_ext` and `librustdoc` for them to provide information about test type.

## Rationale

Rationale for colored output was submitted in #64714

Providing the information about kind of test was also proposed in #64714, and as an additional benefit this information may be useful for the tools using `libtest` (e.g. `cargo`).

Adding flag to treat time limits excess seems logical to me, so projects that do care about test execution time won't have to invent a wheel.

## Backward compatibility

All the changes are completely backward compatible.

## Demo

![rustc_enhanced_time](https://user-images.githubusercontent.com/12111581/65818381-c04f6800-e219-11e9-9875-322463abe24f.gif)

r? @wesleywiser
@bors
Copy link
Contributor

bors commented Oct 13, 2019

☀️ Test successful - checks-azure
Approved by: wesleywiser
Pushing 80b861b to master...

@bors bors added the merged-by-bors This PR was explicitly merged by bors. label Oct 13, 2019
@bors bors merged commit 15f571b into rust-lang:master Oct 13, 2019
@rust-highfive
Copy link
Collaborator

📣 Toolstate changed by #64873!

Tested on commit 80b861b.
Direct link to PR: #64873

💔 clippy-driver on windows: test-pass → test-fail (cc @mcarton @oli-obk @Manishearth @flip1995 @yaahc @phansch @llogiq, @rust-lang/infra).
💔 clippy-driver on linux: test-pass → test-fail (cc @mcarton @oli-obk @Manishearth @flip1995 @yaahc @phansch @llogiq, @rust-lang/infra).
💔 miri on windows: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung, @rust-lang/infra).
💔 miri on linux: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung, @rust-lang/infra).

rust-highfive added a commit to rust-lang-nursery/rust-toolstate that referenced this pull request Oct 13, 2019
Tested on commit rust-lang/rust@80b861b.
Direct link to PR: <rust-lang/rust#64873>

💔 clippy-driver on windows: test-pass → test-fail (cc @mcarton @oli-obk @Manishearth @flip1995 @yaahc @phansch @llogiq, @rust-lang/infra).
💔 clippy-driver on linux: test-pass → test-fail (cc @mcarton @oli-obk @Manishearth @flip1995 @yaahc @phansch @llogiq, @rust-lang/infra).
💔 miri on windows: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung, @rust-lang/infra).
💔 miri on linux: test-pass → test-fail (cc @oli-obk @eddyb @RalfJung, @rust-lang/infra).
@popzxc popzxc deleted the prettify-test-time branch October 13, 2019 04:51
phansch added a commit to phansch/compiletest-rs that referenced this pull request Oct 13, 2019
`report_time` was renamed to `time_options` and is now an `Option`.
@RalfJung RalfJung mentioned this pull request Oct 13, 2019
Manishearth added a commit to Manishearth/compiletest-rs that referenced this pull request Oct 13, 2019
yvt added a commit to yvt/Stella2 that referenced this pull request Nov 12, 2019
For `libtest` tests, this utilizes the unstable rustc feature added by
rust-lang/rust#64873 to meter the execution time.
yvt added a commit to yvt/Stella2 that referenced this pull request Nov 12, 2019
For `libtest` tests, this utilizes the unstable rustc feature added by
rust-lang/rust#64873 to meter the execution time.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
merged-by-bors This PR was explicitly merged by bors. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

8 participants