libtest: Add --report-time flag to print test execution time #64663

jakoschiko · 2019-09-21T17:55:22Z

Implements the flag --report-time to print the execution time of each executed (successful or failed) test.

Example

cargo test -- --report-time produces the following output to stdout:

running 6 tests
test tests::ignore ... ignored
test tests::noop ... ok 0.000s
test tests::should_panic ... ok 0.000s
test tests::panic_after_10millis ... FAILED 0.010s
test tests::sleep_100millis ... ok 0.100s
test tests::sleep_10secs ... ok 10.001s

failures:

---- tests::panic_after_10millis stdout ----
thread 'tests::panic_after_10millis' panicked at 'foo', src\lib.rs:31:9


failures:
    tests::panic_after_10millis

test result: FAILED. 4 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out

cargo test -- --report-time -Z unstable-options --format=json produces the following output to stdout:

{ "type": "suite", "event": "started", "test_count": 6 }
{ "type": "test", "event": "started", "name": "tests::ignore" }
{ "type": "test", "event": "started", "name": "tests::noop" }
{ "type": "test", "event": "started", "name": "tests::panic_after_10millis" }
{ "type": "test", "event": "started", "name": "tests::should_panic" }
{ "type": "test", "name": "tests::ignore", "event": "ignored" }
{ "type": "test", "event": "started", "name": "tests::sleep_100millis" }
{ "type": "test", "name": "tests::noop", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "event": "started", "name": "tests::sleep_10secs" }
{ "type": "test", "name": "tests::should_panic", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "name": "tests::panic_after_10millis", "event": "failed", "exec_time": "0.010s", "stdout": "thread 'tests::panic_after_10millis' panicked at 'foo', src\\lib.rs:31:9\n" }
{ "type": "test", "name": "tests::sleep_100millis", "event": "ok", "exec_time": "0.101s" }
{ "type": "test", "name": "tests::sleep_10secs", "event": "ok", "exec_time": "10.000s" }
{ "type": "suite", "event": "failed", "passed": 4, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 }

cargo test -- --report-time --logfile foo.log produces the following logfile:

ignored tests::ignore
ok tests::noop 0.000s
ok tests::should_panic 0.000s
failed tests::panic_after_10millis 0.010s
ok tests::sleep_100millis 0.100s
ok tests::sleep_10secs 10.001s

rust-highfive · 2019-09-21T17:55:33Z

Thanks for the pull request, and welcome! The Rust team is excited to review your changes, and you should hear from @TimNN (or someone else) soon.

If any changes to this PR are deemed necessary, please add them as extra commits. This ensures that the reviewer can see what has changed since they last reviewed the code. Due to the way GitHub handles out-of-date commits, this should also make it reasonably obvious what issues have or haven't been addressed. Large or tricky changes may require several passes of review and changes.

Please see the contribution instructions for more information.

gnzlbg

I've left some comments (I think it makes sense to start by allowing this only on nightly at first), but otherwise this LGTM.

I'm not sure about the exact formatting, but that is something that can be improved.

src/libtest/lib.rs

jakoschiko · 2019-09-22T20:46:54Z

It's an unstable option now. Should its help message mention that it's unstable? (The help messages of the other unstable options don't mention it.)

I had tried different formatting variants but couldn't decide which to choose. Eventually I just implemented the simplest one (with the precision proposed by the issue).

gnzlbg · 2019-09-23T08:55:33Z

It's an unstable option now. Should its help message mention that it's unstable? (The help messages of the other unstable options don't mention it.)

No, I don't think this is necessary; trying to use it explains what to do.

I had tried different formatting variants but couldn't decide which to choose. Eventually I just implemented the simplest one (with the precision proposed by the issue).

Yes I saw that, I think this is fine for now.

cc @rust-lang/compiler which I think is the team responsible for libtest? cc @Manishearth @alexcrichton

gnzlbg

This LGTM now.

alexcrichton · 2019-09-23T16:55:53Z

I don't believe there's a canonical owner of libtest right now, but this is all behind an unstable flag anyway, so seems fine to me to land in that regard.

@bors: r+

bors · 2019-09-23T16:55:54Z

📌 Commit d91b965 has been approved by alexcrichton

libtest: Add --report-time flag to print test execution time Implements the flag `--report-time` to print the execution time of each executed (successful or failed) test. Closes rust-lang#46610 # Example `cargo test -- --report-time` produces the following output to stdout: ``` running 6 tests test tests::ignore ... ignored test tests::noop ... ok 0.000s test tests::should_panic ... ok 0.000s test tests::panic_after_10millis ... FAILED 0.010s test tests::sleep_100millis ... ok 0.100s test tests::sleep_10secs ... ok 10.001s failures: ---- tests::panic_after_10millis stdout ---- thread 'tests::panic_after_10millis' panicked at 'foo', src\lib.rs:31:9 failures: tests::panic_after_10millis test result: FAILED. 4 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out ``` `cargo test -- --report-time -Z unstable-options --format=json` produces the following output to stdout: ``` { "type": "suite", "event": "started", "test_count": 6 } { "type": "test", "event": "started", "name": "tests::ignore" } { "type": "test", "event": "started", "name": "tests::noop" } { "type": "test", "event": "started", "name": "tests::panic_after_10millis" } { "type": "test", "event": "started", "name": "tests::should_panic" } { "type": "test", "name": "tests::ignore", "event": "ignored" } { "type": "test", "event": "started", "name": "tests::sleep_100millis" } { "type": "test", "name": "tests::noop", "event": "ok", "exec_time": "0.000s" } { "type": "test", "event": "started", "name": "tests::sleep_10secs" } { "type": "test", "name": "tests::should_panic", "event": "ok", "exec_time": "0.000s" } { "type": "test", "name": "tests::panic_after_10millis", "event": "failed", "exec_time": "0.010s", "stdout": "thread 'tests::panic_after_10millis' panicked at 'foo', src\\lib.rs:31:9\n" } { "type": "test", "name": "tests::sleep_100millis", "event": "ok", "exec_time": "0.101s" } { "type": "test", "name": "tests::sleep_10secs", "event": "ok", "exec_time": "10.000s" } { "type": "suite", "event": "failed", "passed": 4, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 } ``` `cargo test -- --report-time --logfile foo.log` produces the following logfile: ``` ignored tests::ignore ok tests::noop 0.000s ok tests::should_panic 0.000s failed tests::panic_after_10millis 0.010s ok tests::sleep_100millis 0.100s ok tests::sleep_10secs 10.001s ```

bors · 2019-09-25T09:54:59Z

⌛ Testing commit d91b965 with merge acf7b50...

libtest: Add --report-time flag to print test execution time Implements the flag `--report-time` to print the execution time of each executed (successful or failed) test. Closes #46610 # Example `cargo test -- --report-time` produces the following output to stdout: ``` running 6 tests test tests::ignore ... ignored test tests::noop ... ok 0.000s test tests::should_panic ... ok 0.000s test tests::panic_after_10millis ... FAILED 0.010s test tests::sleep_100millis ... ok 0.100s test tests::sleep_10secs ... ok 10.001s failures: ---- tests::panic_after_10millis stdout ---- thread 'tests::panic_after_10millis' panicked at 'foo', src\lib.rs:31:9 failures: tests::panic_after_10millis test result: FAILED. 4 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out ``` `cargo test -- --report-time -Z unstable-options --format=json` produces the following output to stdout: ``` { "type": "suite", "event": "started", "test_count": 6 } { "type": "test", "event": "started", "name": "tests::ignore" } { "type": "test", "event": "started", "name": "tests::noop" } { "type": "test", "event": "started", "name": "tests::panic_after_10millis" } { "type": "test", "event": "started", "name": "tests::should_panic" } { "type": "test", "name": "tests::ignore", "event": "ignored" } { "type": "test", "event": "started", "name": "tests::sleep_100millis" } { "type": "test", "name": "tests::noop", "event": "ok", "exec_time": "0.000s" } { "type": "test", "event": "started", "name": "tests::sleep_10secs" } { "type": "test", "name": "tests::should_panic", "event": "ok", "exec_time": "0.000s" } { "type": "test", "name": "tests::panic_after_10millis", "event": "failed", "exec_time": "0.010s", "stdout": "thread 'tests::panic_after_10millis' panicked at 'foo', src\\lib.rs:31:9\n" } { "type": "test", "name": "tests::sleep_100millis", "event": "ok", "exec_time": "0.101s" } { "type": "test", "name": "tests::sleep_10secs", "event": "ok", "exec_time": "10.000s" } { "type": "suite", "event": "failed", "passed": 4, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 } ``` `cargo test -- --report-time --logfile foo.log` produces the following logfile: ``` ignored tests::ignore ok tests::noop 0.000s ok tests::should_panic 0.000s failed tests::panic_after_10millis 0.010s ok tests::sleep_100millis 0.100s ok tests::sleep_10secs 10.001s ```

bors · 2019-09-25T13:49:28Z

☀️ Test successful - checks-azure
Approved by: alexcrichton
Pushing acf7b50 to master...

@wesleywiser

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

nkostoulas · 2019-11-07T11:34:57Z

How do I run this?

$ cargo +nightly test -- --report-time --lib
    Finished test [unoptimized + debuginfo] target(s) in 0.15s
     Running target/debug/deps/coordinator-220d8b237f35464c
error: Unrecognized option: 'lib'
error: test failed, to rerun pass '--lib'

eddyb · 2019-11-07T14:04:37Z

@nkostoulas If --lib is a cargo test flag, you need to pass it before --.

nkostoulas · 2019-11-07T14:13:13Z

Sorry I copied the wrong segment

$ cargo +nightly test -- --report-time
    Finished test [unoptimized + debuginfo] target(s) in 0.16s
     Running target/debug/deps/coordinator-220d8b237f35464c
error: The "report-time" flag is only accepted on the nightly compiler
error: test failed, to rerun pass '--lib'

$ cargo test -- --report-time
    Finished dev [unoptimized + debuginfo] target(s) in 0.34s
     Running target/debug/deps/coordinator-6d69e1ee36b403d9
error: Unrecognized option: 'report-time'
error: test failed, to rerun pass '--lib'

Not sure what --lib is.

jakoschiko · 2019-11-07T14:24:05Z

report-time is currently unstable. Try:

cargo +nightly test -- -Z unstable-options --report-time

cargo test -- --help shows the parameters that can be used after the --.

nkostoulas · 2019-11-07T14:48:59Z

cheers!

matklad · 2020-08-19T21:13:04Z

Note that nightly toolchain is not required for this, cargo t -- --report-time -Z unstable-options works.

jakoschiko · 2020-08-23T20:54:32Z

Note that nightly toolchain is not required for this, cargo t -- --report-time -Z unstable-options works.

Could this be a bug? This is from library/test/src/cli.rs:

if let Some(opt) = matches.opt_str("Z") {
    if !is_nightly() {
        return Err("the option `Z` is only accepted on the nightly compiler".into());
    }
    ...
}

If I remember correctly nightly toolchain was needed when I made the PR.
Edit: See #75526

matklad · 2021-02-17T09:52:36Z

I wonder if we should have some kind of a tracking issue for this and #75752? I personally would love to see both of this stabilized sooner than later, as they are a tremendous help for large complicated projects with many engineers.

jakoschiko · 2021-02-17T18:33:31Z

There is #64888.
I also would like to see this stabilized, but I don't know the process. And I think more tests would be necessary, as far as I know there are no UI tests that check the output.

Edit: btw, #75752 is already stable

libtest: Add --report-time flag to print test execution time

c16a547

rust-highfive assigned TimNN Sep 21, 2019

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Sep 21, 2019

gnzlbg reviewed Sep 22, 2019

View reviewed changes

src/libtest/lib.rs Show resolved Hide resolved

src/libtest/lib.rs Outdated Show resolved Hide resolved

libtest: Make --report-time an unstable option

d91b965

gnzlbg approved these changes Sep 23, 2019

View reviewed changes

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 Sep 23, 2019

Centril mentioned this pull request Sep 23, 2019

Rollup of 7 pull requests #64713

Closed

fbstj mentioned this pull request Sep 23, 2019

Add --measure-time flag to libtest #64714

Closed

bors added the merged-by-bors This PR was explicitly merged by bors. label Sep 25, 2019

bors merged commit d91b965 into rust-lang:master Sep 25, 2019

This was referenced Sep 25, 2019

panic=abort support in libtest #64158

Merged

Include message on tests that should panic but do not #64745

Merged

matthiaskrgr mentioned this pull request Sep 25, 2019

does not build with latest rustc Manishearth/compiletest-rs#186

Closed

jakoschiko deleted the report-time branch September 26, 2019 17:49

EFanZh mentioned this pull request Sep 28, 2019

Add execution time support johnterickson/cargo2junit#15

Closed

popzxc mentioned this pull request Sep 28, 2019

Enhance report-time option #64873

Merged

thedavidmeister mentioned this pull request Oct 1, 2019

test timing report compatible rust version holochain/holonix-archive#69

Closed

matklad mentioned this pull request Aug 18, 2020

By default, print the total time taken to execute a test suite #75660

Closed

jakoschiko mentioned this pull request Nov 21, 2020

libtest: Print the total time taken to execute a test suite #75752

Merged

matklad mentioned this pull request Feb 17, 2021

Handle timed out tests in CI / display reasonable data about failed tests in CI near/nearcore#3963

Closed

Robert-Steiner mentioned this pull request Mar 19, 2021

CI build mobile libs xaynetwork/xayn_ai#21

Merged

20 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

libtest: Add --report-time flag to print test execution time #64663

libtest: Add --report-time flag to print test execution time #64663

jakoschiko commented Sep 21, 2019

rust-highfive commented Sep 21, 2019

gnzlbg left a comment •

edited

Loading

jakoschiko commented Sep 22, 2019

gnzlbg commented Sep 23, 2019

gnzlbg left a comment

alexcrichton commented Sep 23, 2019

bors commented Sep 23, 2019

bors commented Sep 25, 2019

bors commented Sep 25, 2019

nkostoulas commented Nov 7, 2019

eddyb commented Nov 7, 2019

nkostoulas commented Nov 7, 2019 •

edited

Loading

jakoschiko commented Nov 7, 2019

nkostoulas commented Nov 7, 2019

matklad commented Aug 19, 2020

jakoschiko commented Aug 23, 2020 •

edited

Loading

matklad commented Feb 17, 2021

jakoschiko commented Feb 17, 2021 •

edited

Loading

libtest: Add --report-time flag to print test execution time #64663

libtest: Add --report-time flag to print test execution time #64663

Conversation

jakoschiko commented Sep 21, 2019

Example

rust-highfive commented Sep 21, 2019

gnzlbg left a comment • edited Loading

Choose a reason for hiding this comment

jakoschiko commented Sep 22, 2019

gnzlbg commented Sep 23, 2019

gnzlbg left a comment

Choose a reason for hiding this comment

alexcrichton commented Sep 23, 2019

bors commented Sep 23, 2019

bors commented Sep 25, 2019

bors commented Sep 25, 2019

nkostoulas commented Nov 7, 2019

eddyb commented Nov 7, 2019

nkostoulas commented Nov 7, 2019 • edited Loading

jakoschiko commented Nov 7, 2019

nkostoulas commented Nov 7, 2019

matklad commented Aug 19, 2020

jakoschiko commented Aug 23, 2020 • edited Loading

matklad commented Feb 17, 2021

jakoschiko commented Feb 17, 2021 • edited Loading

gnzlbg left a comment •

edited

Loading

nkostoulas commented Nov 7, 2019 •

edited

Loading

jakoschiko commented Aug 23, 2020 •

edited

Loading

jakoschiko commented Feb 17, 2021 •

edited

Loading