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

jakoschiko · 2020-08-20T22:30:51Z

Print the total time taken to execute a test suite by default, without any kind of flag.

Example

anon@anon:~/code/rust/example$ cargo test
   Compiling example v0.1.0 (/home/anon/code/rust/example)
    Finished test [unoptimized + debuginfo] target(s) in 0.18s
     Running target/debug/deps/example-745b64d3885c3565

running 3 tests
test tests::foo ... ok
test tests::bar ... ok
test tests::baz ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.2s

   Doc-tests example

running 3 tests
test src/lib.rs - foo (line 3) ... ok
test src/lib.rs - bar (line 11) ... ok
test src/lib.rs - baz (line 19) ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.3s

anon@anon:~/code/rust/example$ cargo test -- --format terse
    Finished test [unoptimized + debuginfo] target(s) in 0.08s
     Running target/debug/deps/example-745b64d3885c3565

running 3 tests
...
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.2s

   Doc-tests example

running 3 tests
...
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.3s

anon@anon:~/code/rust/example$ cargo test -- --format json -Z unstable-options
   Compiling example v0.1.0 (/home/anon/code/rust/example)
    Finished test [unoptimized + debuginfo] target(s) in 0.25s
     Running target/debug/deps/example-745b64d3885c3565
{ "type": "suite", "event": "started", "test_count": 3 }
{ "type": "test", "event": "started", "name": "tests::bar" }
{ "type": "test", "event": "started", "name": "tests::baz" }
{ "type": "test", "event": "started", "name": "tests::foo" }
{ "type": "test", "name": "tests::foo", "event": "ok" }
{ "type": "test", "name": "tests::bar", "event": "ok" }
{ "type": "test", "name": "tests::baz", "event": "ok" }
{ "type": "suite", "event": "ok", "passed": 3, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": "1.2s" }
   Doc-tests example
{ "type": "suite", "event": "started", "test_count": 3 }
{ "type": "test", "event": "started", "name": "src/lib.rs - bar (line 11)" }
{ "type": "test", "event": "started", "name": "src/lib.rs - baz (line 19)" }
{ "type": "test", "event": "started", "name": "src/lib.rs - foo (line 3)" }
{ "type": "test", "name": "src/lib.rs - foo (line 3)", "event": "ok" }
{ "type": "test", "name": "src/lib.rs - bar (line 11)", "event": "ok" }
{ "type": "test", "name": "src/lib.rs - baz (line 19)", "event": "ok" }
{ "type": "suite", "event": "ok", "passed": 3, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": 0, "exec_time": "1.3s" }

rust-highfive · 2020-08-20T22:30:55Z

r? @LukasKalbertodt

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

matklad · 2020-08-21T12:58:31Z

library/test/src/time.rs

+
+impl fmt::Display for TestSuiteExecTime {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "{:.1}s", self.0.as_secs_f64())


I wonder what's the best precision here, .1 seems a bit to coarse-grained here. Cargo uses two decimal digits ( Finished test [unoptimized] target(s) in 3.91s), so let's do this as well?

jakoschiko · 2020-08-21T22:28:54Z

Small problem: The default width of my terminal is 80. The width of test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; 1.31s is 82. That makes me feel unwell.

Bigger problem: There are two tests (ui/test-panic-abort-nocapture.rs and ui/test-panic-abort.rs) that expect deterministic output for the test suite and I don't know how to fix that.

matklad · 2020-08-21T22:37:17Z

Small problem: The default width of my terminal is 80

I think libtest already assumes wider than 80 terminal:

λ cargo qt
    Finished test [unoptimized] target(s) in 0.13s
     Running target/debug/deps/arena-bf0145d0690d0fbc

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running target/debug/deps/assists-7caa4796fb877477

running 475 tests
.................................................................................................... 100/475
...............................................................................i....i............... 200/475
..........................ii.i............ii........................................................ 300/475
.................................................................................................... 400/475
...........................................................................
test result: ok. 468 passed; 0 failed; 7 ignored; 0 measured; 0 filtered out

that expect deterministic output for the test suite and I don't know how to fix that.

I am not familiar enough with compiletest, but a nuclear option would be a -Z flag to set times to zero or something like that.

jakoschiko · 2020-08-23T20:04:36Z

Setting the time to zero sounds reasonable.

The documentation says rustc is run with -Z ui-testing when compiling the UI tests. Can I check that flag at compile time? This would be better than adding another -Z flag to libtest.

jakoschiko · 2020-08-23T22:20:30Z

Can I check that flag at compile time?

I found no clues in the source code that this is possible. Therefore I implemented -Z ui-testing for libtest.

Does this need further documentation?
Is it confusing that it uses the same name as rustc's -Z ui-testing?

LukasKalbertodt · 2020-08-26T19:44:40Z

Great idea; that sounds very useful!

I think a better way to fix the "test output" problem is to use custom normalization of the output, as described here. I haven't looked into it in detail, but it seems like we can regex-replace the actual output before it is compared to the .stdout file. (If you need help with this, I can of course look into it more thoroughly.)
I would much prefer that over an unstable flag, especially since the flag is responsible for a large part of code changes in this PR.

And I think the output should say something like finished in 3s or something like that, not just print the time.

jakoschiko · 2020-08-26T20:35:04Z

Normalization works great! I also changed the output as proposed, this helped to find the text that needs to be normalized.

anon@anon:~/code/rust/example$ cargo +stage1 test
   Compiling example v0.1.0 (/home/anon/code/rust/example)
    Finished test [unoptimized + debuginfo] target(s) in 0.26s
     Running target/debug/deps/example-745b64d3885c3565

running 3 tests
test tests::foo ... ok
test tests::bar ... ok
test tests::baz ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.20s

   Doc-tests example

running 3 tests
test src/lib.rs - foo (line 3) ... ok
test src/lib.rs - bar (line 11) ... ok
test src/lib.rs - baz (line 19) ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.32s

jakoschiko · 2020-08-26T21:37:58Z

Yet another failing test:
src/test/run-make-fulldeps/libtest-json runs libtest with JSON format via a Makefile, redirects the output into a file, checks for valid JSON and compares the actual output with a file containing the expected output. Problem: The actual output is nondeterministic.

Possible solutions:

Don't add the execution time to the JSON output. This was not requested, but I thought it makes sense.
Reintroduce an unstable flag that ensures deterministic output. This was already done and required too many changes.
Use a CLI tool to normalize the actual output. Which tools are allowed to be used?

Any advice?

LukasKalbertodt · 2020-08-26T21:48:15Z

Looks much better now!

The second test failure is unfortunate. I am not sure how to best fix this :/
I would tend to believe that the execution time in the JSON output isn't as important, but I am not sure if there are some guidelines on what to include there. I also have no CLI idea what tools can be used in that test.
While I don't particularly like the unstable flag, it might still be a valid solution.

But in general, I'm not sure I am the correct person to review this (doesn't seem like a libs issue). Maaaybe @rust-lang/devtools can help out?

Mark-Simulacrum · 2020-08-26T21:49:15Z

I suspect that normalizing the JSON output shouldn't be too hard -- we can use anything on CI, probably, but something liked sed should do the trick and I think is likely already used in other run-make tests.

jakoschiko · 2020-08-26T22:39:54Z

Thanks, I fixed the test with sed.

And yes, sed is already used, for example in src/test/run-make-fulldeps/stable-symbol-names/Makefile.

Manishearth · 2020-08-27T03:04:05Z

I would say libtest is a libs team concern

LukasKalbertodt · 2020-08-30T10:31:15Z

I would say libtest is a libs team concern

Well then!

@bors r+

Thanks again for the PR!

bors · 2020-08-30T10:31:17Z

📌 Commit f8d0857135c216621c39edefbb2ecddb26d2208a has been approved by LukasKalbertodt

matklad · 2020-08-30T10:33:36Z

This is not gated, right? Then this should hit relnotes

bors · 2020-08-30T10:59:21Z

⌛ Testing commit f8d0857135c216621c39edefbb2ecddb26d2208a with merge 9d4918d9118417d0a46db7131fc474ec0ac3ee9b...

bors · 2020-08-30T11:25:48Z

💔 Test failed - checks-actions

m-ou-se · 2020-11-28T10:17:08Z

Spurious error:

error: failed to download from `https://crates.io/api/v1/crates/rustc-demangle/0.1.18/download`

Caused by:
  [55] Failed sending data to the peer (Connection died, tried 5 times before giving up)

@bors retry

bors · 2020-11-28T12:40:31Z

⌛ Testing commit fe3daea10414fd9ba1e956ee1bcf23db07c8a7c2 with merge ed9f6cafa75fbe0e18198e6fabcdf75e7d5e1b1e...

bors · 2020-11-28T14:46:16Z

💔 Test failed - checks-actions

m-ou-se · 2020-11-28T15:11:08Z

Oh, apparently POSIX doesn't even require \+ to be supported.

I think this would work:

sed 's/"exec_time": [0-9.]*/"exec_time": $$TIME/'

jakoschiko · 2020-11-29T01:18:54Z

@m-ou-se Thanks, I changed the latest commit accordingly.

Dylan-DPC-zz · 2020-11-29T02:40:22Z

@bors r=@m-ou-se

bors · 2020-11-29T02:40:23Z

📌 Commit 322f53d has been approved by m-ou-se

bors · 2020-11-29T04:54:26Z

⌛ Testing commit 322f53d with merge 6add378...

bors · 2020-11-29T07:05:42Z

☀️ Test successful - checks-actions
Approved by: m-ou-se
Pushing 6add378 to master...

jakoschiko · 2020-11-29T08:52:30Z

Thanks for the help!

m-ou-se · 2020-11-29T10:25:53Z

@jakoschiko Thanks for all your work to make this happen!

… r=alexcrichton Relaxes expectation of `cargo test` tests to accept test execution time rust-lang/rust#75752 changes the output of libtest. For example, output before: ``` test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out ``` Output after: ``` test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s ``` This breaks some cargo tests: https://github.com/rust-lang-ci/rust/runs/1439245145 As a preparation for the merge, this PR relaxes the test expectations of `cargo test` tests to accept both outputs. I'm using the existing pattern feature of `Execs::with_stdout`: ``` test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out[..] ``` I made this change for the following tests: - `test::can_not_mix_doc_tests_and_regular_tests` - `test::cargo_test_quiet_with_harness` - `test::test_filtered_excludes_compiling_examples` - `test::cargo_test_doctest_xcompile_ignores` (didn't fail in rust-lang/rust#79317, but failed locally) - `test::cargo_test_doctest_xcompile` (doesn't run locally, I changed it just to be safe) - `test::cargo_test_doctest_xcompile_runner` (doesn't run locally, I changed it just to be safe) - `test::cargo_test_doctest_xcompile_no_runner` (doesn't run locally, I changed it just to be safe) If requested, I will open another PR later to change the expectation to: ``` test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in [..]s ``` However, I don't know how to handle WASM targets because WASM doesn't support time measuring, therefore the libtest output didn't change for WASM. Is WASM even relevant here?

Pkgsrc changes: * Adjust patches, re-compute line offsets, fix capitalization. * Remove i686/FreeBSD support, no longer provided upstream. * Bump bootstraps to 1.49.0. * Change USE_TOOLS from bsdtar to gtar. * Reduce diffs to pkgsrc-wip package patches. * Allow rust.BUILD_TARGET to override automatic choice of target. * Add an i586/NetBSD (pentium) bootstrap variant (needs testing), not yet added as bootstrap since 1.49 doesn't have that variant. Upstream changes: Version 1.50.0 (2021-02-11) ============================ Language ----------------------- - [You can now use `const` values for `x` in `[x; N]` array expressions.][79270] This has been technically possible since 1.38.0, as it was unintentionally stabilized. - [Assignments to `ManuallyDrop<T>` union fields are now considered safe.][78068] Compiler ----------------------- - [Added tier 3\* support for the `armv5te-unknown-linux-uclibceabi` target.][78142] - [Added tier 3 support for the `aarch64-apple-ios-macabi` target.][77484] - [The `x86_64-unknown-freebsd` is now built with the full toolset.][79484] \* Refer to Rust's [platform support page][forge-platform-support] for more information on Rust's tiered platform support. Libraries ----------------------- - [`proc_macro::Punct` now implements `PartialEq<char>`.][78636] - [`ops::{Index, IndexMut}` are now implemented for fixed sized arrays of any length.][74989] - [On Unix platforms, the `std::fs::File` type now has a "niche" of `-1`.][74699] This value cannot be a valid file descriptor, and now means `Option<File>` takes up the same amount of space as `File`. Stabilized APIs --------------- - [`bool::then`] - [`btree_map::Entry::or_insert_with_key`] - [`f32::clamp`] - [`f64::clamp`] - [`hash_map::Entry::or_insert_with_key`] - [`Ord::clamp`] - [`RefCell::take`] - [`slice::fill`] - [`UnsafeCell::get_mut`] The following previously stable methods are now `const`. - [`IpAddr::is_ipv4`] - [`IpAddr::is_ipv6`] - [`Layout::size`] - [`Layout::align`] - [`Layout::from_size_align`] - `pow` for all integer types. - `checked_pow` for all integer types. - `saturating_pow` for all integer types. - `wrapping_pow` for all integer types. - `next_power_of_two` for all unsigned integer types. - `checked_power_of_two` for all unsigned integer types. Cargo ----------------------- - [Added the `[build.rustc-workspace-wrapper]` option.][cargo/8976] This option sets a wrapper to execute instead of `rustc`, for workspace members only. - [`cargo:rerun-if-changed` will now, if provided a directory, scan the entire contents of that directory for changes.][cargo/8973] - [Added the `--workspace` flag to the `cargo update` command.][cargo/8725] Misc ---- - [The search results tab and the help button are focusable with keyboard in rustdoc.][79896] - [Running tests will now print the total time taken to execute.][75752] Compatibility Notes ------------------- - [The `compare_and_swap` method on atomics has been deprecated.][79261] It's recommended to use the `compare_exchange` and `compare_exchange_weak` methods instead. - [Changes in how `TokenStream`s are checked have fixed some cases where you could write unhygenic `macro_rules!` macros.][79472] - [`#![test]` as an inner attribute is now considered unstable like other inner macro attributes, and reports an error by default through the `soft_unstable` lint.][79003] - [Overriding a `forbid` lint at the same level that it was set is now a hard error.][78864] - [Dropped support for all cloudabi targets.][78439] - [You can no longer intercept `panic!` calls by supplying your own macro.][78343] It's recommended to use the `#[panic_handler]` attribute to provide your own implementation. - [Semi-colons after item statements (e.g. `struct Foo {};`) now produce a warning.][78296] [74989]: rust-lang/rust#74989 [79261]: rust-lang/rust#79261 [79896]: rust-lang/rust#79896 [79484]: rust-lang/rust#79484 [79472]: rust-lang/rust#79472 [79270]: rust-lang/rust#79270 [79003]: rust-lang/rust#79003 [78864]: rust-lang/rust#78864 [78636]: rust-lang/rust#78636 [78439]: rust-lang/rust#78439 [78343]: rust-lang/rust#78343 [78296]: rust-lang/rust#78296 [78068]: rust-lang/rust#78068 [75752]: rust-lang/rust#75752 [74699]: rust-lang/rust#74699 [78142]: rust-lang/rust#78142 [77484]: rust-lang/rust#77484 [cargo/8976]: rust-lang/cargo#8976 [cargo/8973]: rust-lang/cargo#8973 [cargo/8725]: rust-lang/cargo#8725 [`IpAddr::is_ipv4`]: https://doc.rust-lang.org/stable/std/net/enum.IpAddr.html#method.is_ipv4 [`IpAddr::is_ipv6`]: https://doc.rust-lang.org/stable/std/net/enum.IpAddr.html#method.is_ipv6 [`Layout::align`]: https://doc.rust-lang.org/stable/std/alloc/struct.Layout.html#method.align [`Layout::from_size_align`]: https://doc.rust-lang.org/stable/std/alloc/struct.Layout.html#method.from_size_align [`Layout::size`]: https://doc.rust-lang.org/stable/std/alloc/struct.Layout.html#method.size [`Ord::clamp`]: https://doc.rust-lang.org/stable/std/cmp/trait.Ord.html#method.clamp [`RefCell::take`]: https://doc.rust-lang.org/stable/std/cell/struct.RefCell.html#method.take [`UnsafeCell::get_mut`]: https://doc.rust-lang.org/stable/std/cell/struct.UnsafeCell.html#method.get_mut [`bool::then`]: https://doc.rust-lang.org/stable/std/primitive.bool.html#method.then [`btree_map::Entry::or_insert_with_key`]: https://doc.rust-lang.org/stable/std/collections/btree_map/enum.Entry.html#method.or_insert_with_key [`f32::clamp`]: https://doc.rust-lang.org/stable/std/primitive.f32.html#method.clamp [`f64::clamp`]: https://doc.rust-lang.org/stable/std/primitive.f64.html#method.clamp [`hash_map::Entry::or_insert_with_key`]: https://doc.rust-lang.org/stable/std/collections/hash_map/enum.Entry.html#method.or_insert_with_key [`slice::fill`]: https://doc.rust-lang.org/stable/std/primitive.slice.html#method.fill

rust-highfive assigned LukasKalbertodt Aug 20, 2020

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 20, 2020

matklad reviewed Aug 21, 2020

View reviewed changes

jakoschiko force-pushed the test-suite-time branch from cb1f9e6 to 731566a Compare August 26, 2020 20:34

jakoschiko force-pushed the test-suite-time branch from 731566a to 4c76122 Compare August 26, 2020 22:39

jakoschiko force-pushed the test-suite-time branch from 4c76122 to f8d0857 Compare August 26, 2020 23:31

jyn514 added A-libtest Area: `#[test]` / the `test` library T-libs-api Relevant to the library API team, which will review and decide on the PR/issue. labels Aug 28, 2020

LukasKalbertodt approved these changes Aug 30, 2020

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 Aug 30, 2020

matklad added the relnotes Marks issues that should be documented in the release notes of the next release. label Aug 30, 2020

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 Nov 28, 2020

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 Nov 28, 2020

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 Nov 28, 2020

libtest: Make sed arguments compatible with apple

322f53d

jakoschiko force-pushed the test-suite-time branch from fe3daea to 322f53d Compare November 29, 2020 01:17

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 Nov 29, 2020

bors added the merged-by-bors This PR was explicitly merged by bors. label Nov 29, 2020

bors merged commit 6add378 into rust-lang:master Nov 29, 2020

rustbot added this to the 1.50.0 milestone Nov 29, 2020

jakoschiko deleted the test-suite-time branch November 29, 2020 08:49

This was referenced Feb 17, 2021

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

Merged

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

Closed

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

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

Uh oh!

Conversation

jakoschiko commented Aug 20, 2020

Example

Uh oh!

rust-highfive commented Aug 20, 2020

Uh oh!

matklad Aug 21, 2020

Choose a reason for hiding this comment

Uh oh!

jakoschiko Aug 21, 2020

Choose a reason for hiding this comment

Uh oh!

jakoschiko commented Aug 21, 2020

Uh oh!

matklad commented Aug 21, 2020

Uh oh!

jakoschiko commented Aug 23, 2020

Uh oh!

jakoschiko commented Aug 23, 2020

Uh oh!

LukasKalbertodt commented Aug 26, 2020

Uh oh!

jakoschiko commented Aug 26, 2020

Uh oh!

jakoschiko commented Aug 26, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

LukasKalbertodt commented Aug 26, 2020

Uh oh!

Mark-Simulacrum commented Aug 26, 2020

Uh oh!

jakoschiko commented Aug 26, 2020

Uh oh!

Manishearth commented Aug 27, 2020

Uh oh!

LukasKalbertodt commented Aug 30, 2020

Uh oh!

bors commented Aug 30, 2020

Uh oh!

matklad commented Aug 30, 2020

Uh oh!

bors commented Aug 30, 2020

Uh oh!

bors commented Aug 30, 2020

Uh oh!

m-ou-se commented Nov 28, 2020

Uh oh!

bors commented Nov 28, 2020

Uh oh!

bors commented Nov 28, 2020

Uh oh!

m-ou-se commented Nov 28, 2020

Uh oh!

jakoschiko commented Nov 29, 2020

Uh oh!

Dylan-DPC-zz commented Nov 29, 2020

Uh oh!

bors commented Nov 29, 2020

Uh oh!

bors commented Nov 29, 2020

Uh oh!

bors commented Nov 29, 2020

Uh oh!

jakoschiko commented Nov 29, 2020

Uh oh!

m-ou-se commented Nov 29, 2020

Uh oh!

Uh oh!

jakoschiko commented Aug 26, 2020 •

edited

Loading