Tracking issue for report-time

[popzxc]

Tracks stabilization for the report-time and ensure-test-time libtest options.

[smoelius]

I propose that the methods for enabling and configuring this option be changed.

The option currently uses optflagopt, which means that one must use = to specify its parameter, e.g., --report-time=colored. If one doesn't use =, then the would-be parameter is interpreted as a filter, which is confusing. The difference is further jarring because no other libtest option uses optflagopt. Finally, the current implementation of --report-time does not produce an error when its parameter is not plain or colored.

I propose:

• the option be split into two options: --report-time, to enable the option, and --report-time-color, to configure the option
• the latter use optopt not optflagopt, so that use of = is optional when specifying the parameter
• the valid parameters to --report-time-color be always, never, and (if feasible) auto (the default) (These choices seem more conventional than plain and colored.)
• --report-time-color produce an error if its parameter is not among the three valid choices

Do others have opinions?

[matklad]

Note that cargo stabilized --timings option. I think it'll be best if we name libtest option the same, i.e., rename --report-time to --timings.

[Ancient123]

Hoping this can get released to stable soon now that -Zunstable-options --report-time no longer works on stable rust version. 😢

[sourcefrog]

I was trying this out to focus on some slow tests.

One small feedback: according to ehuss in #115989 the times are measured in milliseconds, but the doc https://doc.rust-lang.org/beta/unstable-book/compiler-flags/report-time.html and help strings don't specify the units.

However, beyond that, I can see that --report-time works, which is great, but --ensure-time and the time-limiting vars don't seem to work on integration tests?

With rustc 1.76.0-nightly (d86d65bbc 2023-12-10) on 98d502b639 of https://github.com/sourcefrog/cargo-mutants:

; env RUST_TEST_TIME_UNIT=50,100 cargo +nightly test -- -Zunstable-options --report-time --ensure-time
    Finished test [unoptimized + debuginfo] target(s) in 0.05s
     Running unittests src/main.rs (target/debug/deps/cargo_mutants-a5abd64a2826343e)

running 78 tests
test console::test::test_duration_minutes_seconds ... ok <0.000s>
test fnvalue::test::box_usize_replacement ... ok <0.000s>
test fnvalue::test::box_unrecognized_type_replacement ... ok <0.000s>
...
test output::test::rotate ... FAILED (time limit exceeded) <0.102s>
test visit::test::expected_mutants_for_own_source_tree ... FAILED (time limit exceeded) <0.180s>

Great, that failed as it should have.

But on an integration test:

; env RUST_TEST_TIME_INTEGRATION=50,100 RUST_TEST_TIME_UNIT=50,100 cargo +nightly test --test cli -- -Zunstable-options --report-time --ensure-time
    Finished test [unoptimized + debuginfo] target(s) in 0.05s
     Running tests/cli/main.rs (target/debug/deps/cli-d36846210cc3addb)

running 97 tests
...
test jobs::jobs_option_accepted ... ok <9.147s>
test mutants_causing_tests_to_hang_are_stopped_by_manual_timeout ... ok <11.344s>
test well_tested_tree_finds_no_problems ... ok <16.703s>
test well_tested_tree_quiet ... ok <16.651s>

Even the tests that take much longer than either limit don't fail, and they aren't colored or highlighted either.

[alejandrodnm]

I've been trying RUST_TEST_TIME_INTEGRATION and it's not working.

[jakoschiko]

@sourcefrog @alejandrodnm

I tested it with the most recent compiler and it worked for me.

> cargo +nightly --version
cargo 1.78.0-nightly (ccc84ccec 2024-02-07)

> tree -I target
.
├── Cargo.lock
├── Cargo.toml
├── src
│   └── lib.rs
└── tests
    └── example.rs

> cat tests/example.rs
#[test]
fn integration_test_fast() {
    std::thread::sleep(std::time::Duration::from_millis(12))
}

#[test]
fn integration_test_slow() {
    std::thread::sleep(std::time::Duration::from_millis(1234))
}

#[test]
fn integration_test_very_slow() {
    std::thread::sleep(std::time::Duration::from_millis(12345))
}

> env RUST_TEST_TIME_INTEGRATION=50,100 RUST_TEST_TIME_UNIT=50,100 cargo +nightly test --test example -- -Zunstable-options --report-time --ensure-time
    Finished test [unoptimized + debuginfo] target(s) in 0.00s
     Running tests/example.rs (target/debug/deps/example-cc2e736b09617b55)

running 3 tests
test integration_test_fast ... ok <0.012s>
test integration_test_slow ... FAILED (time limit exceeded) <1.234s>
test integration_test_very_slow ... FAILED (time limit exceeded) <12.345s>

failures (time limit exceeded):

failures (time limit exceeded):
    integration_test_slow
    integration_test_very_slow

test result: FAILED. 1 passed; 2 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.35s

error: test failed, to rerun pass `--test example`

I suggest creating an issue with a minimal example. If you mention me, I'll dig into it.

[jakoschiko]

Note that cargo stabilized --timings option. I think it'll be best if we name libtest option the same, i.e., rename --report-time to --timings.

The --timings option of cargo is a rather complicated feature, while the --report-time option of libtest simply add the execution time to the existing output. How about removing the --report-time option and print the execution time by default? IMO this information provides valuable feedback most of the time and there are almost no drawbacks.

[sourcefrog]

@jakoschiko I made a small reproduction similar to yours and it works as expected:

; env RUST_TEST_TIME_INTEGRATION=50,100 RUST_TEST_TIME_UNIT=50,100
 cargo +nightly test --test cli -- -Zunstable-options --report-time --ensure-time
   Compiling rust-report-time-repro v0.1.0 (/home/mbp/src/rust-report-time-repro)
    Finished test [unoptimized + debuginfo] target(s) in 0.16s
     Running tests/cli.rs (target/debug/deps/cli-c84202f49f5e5e6e)

running 1 test
test slow_test ... FAILED (time limit exceeded) <10.000s>

failures (time limit exceeded):

---- slow_test stdout ----
Slow test starting...
Slow test done.


failures (time limit exceeded):
    slow_test

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 10.00s

However, when I try the exact same command in the cargo-mutants repo, it shows the times but it does not flag any failures. It's very surprising. I don't think mutants is doing anything especially strange to interfere with the normal working of the test harness.

; env RUST_TEST_TIME_INTEGRATION=50,100 RUST_TEST_TIME_UNIT=50,100 cargo +nightly test --test cli -- -Zunstable-options --report-time --ensure-time
    Finished test [unoptimized + debuginfo] target(s) in 0.05s
     Running tests/cli/main.rs (target/debug/deps/cli-7f3da6fc93e09d30)

running 106 tests
test colors::invalid_cargo_term_color_rejected_with_message ... ok <0.004s>
test completions_option_generates_something ... ok <0.021s>
...
test well_tested_tree_check_only ... ok <5.303s>
test log_file_names_are_short_and_dont_collide ... ok <7.172s>
test well_tested_tree_check_only_shuffled ... ok <5.593s>
test tree_with_child_directories_is_well_tested ... ok <6.808s>
test mutants_causing_tests_to_hang_are_stopped_by_manual_timeout ... ok <12.376s>
test well_tested_tree_finds_no_problems ... ok <19.610s>

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

As you can see some of these tests took much longer than the limit...

I wondered if it was something about running multiple threads in parallel throwing off the timing, so I tried with --test-threads 1, but that did not fix it.

So, I don't know how to minimize it, but you should at least be able to reproduce this from the cargo-mutants public repo.

[jakoschiko]

Can confirm, will investigate.

[jakoschiko]

@sourcefrog Your repository doesn't have any integration tests :p

Usually an integration test has a path like this:

my_crate/tests/cli.rs // contains #[test] functions

In your case the path looks like this:

my_crate/tests/cli/main.rs // contains #[test] functions but no main function

This in neither documented here nor here. Surprisingly it does work, but the implementation of the #[test] macro will emit the test type TestType::Unknown:

if crate_path.ends_with("src") {
    // `/src` folder contains unit-tests.
    TestType::UnitTest
} else if crate_path.ends_with("tests") {
    // `/tests` folder contains integration tests.
    TestType::IntegrationTest
} else {
    // Crate layout doesn't match expected one, test type is unknown.
    TestType::Unknown
}

So technically RUST_TEST_TIME_INTEGRATION does work as expected. Nevertheless, this is unsatisfactory.

[sourcefrog]

Fascinating, well found. `cargo metadata` and `cargo test` see it as a test target, but you're quite right it doesn't match what the docs specify, which is that they need to be directly within `tests`.