Include executed tests in the build metrics (and use a custom test display impl)

[pietroalbini]

The main goal of this PR is to include all tests executed in CI inside the build metrics JSON files. I need this for Ferrocene, and @Mark-Simulacrum expressed desire to have this as well to ensure all tests are executed at least once somewhere in CI.

Unfortunately implementing this required rewriting inside of bootstrap all of the code to render the test output to console. libtest supports outputting JSON instead of raw text, which we can indeed use to populate the build metrics. Doing that suppresses the console output though, and compared to rustc and Cargo the console output is not included as a JSON field.

Because of that, this PR had to reimplement both the "pretty" format (one test per line, with rust.verbose-tests = true), and the "terse" format (the wall of dots, with rust.verbose-tests = false). The current implementation should have the exact same output as libtest, except for the benchmark output. libtest's benchmark output is broken in the "terse" format, so since that's our default I slightly improved how it's rendered.

Also, to bring parity with libtest I had to introduce support for coloring output from bootstrap, using the same dependencies annotate-snippets uses. It's now possible to use builder.color_for_stdout(Color::Red, "text") and builder.color_for_stderr(Color::Green, "text") across all of bootstrap, automatically respecting the --color flag and whether the stream is a terminal or not.

I recommend reviewing the PR commit-by-commit.
r? @Mark-Simulacrum

[ehuss]

I noticed this removes the output from Cargo and places it at the end. For example, it now shows:

running 0 tests


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


running 49 tests
.................................................

test result: ok. 49 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 4.69ms


running 19 tests
...................

test result: ok. 19 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.82ms


running 15 tests
...............

test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 28.05ms

instead of:

running 0 tests

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

     Running tests/ieee.rs (obj/build/x86_64-unknown-linux-gnu/stage1-rustc/x86_64-unknown-linux-gnu/release/deps/ieee-c3f97d5f9513b69f)

running 49 tests
.................................................
test result: ok. 49 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/ppc.rs (obj/build/x86_64-unknown-linux-gnu/stage1-rustc/x86_64-unknown-linux-gnu/release/deps/ppc-8d20debf1e8d2487)

running 19 tests
...................
test result: ok. 19 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running unittests src/lib.rs (obj/build/x86_64-unknown-linux-gnu/stage1-rustc/x86_64-unknown-linux-gnu/release/deps/rustc_arena-d805e744b0c02363)

running 15 tests
...............
test result: ok. 15 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s

Because it delays writing the stderr till the end. That can make it difficult to see which test suite is running at any one time. It also removes any sense of progress, as you just see it hang while cargo is building things (no progress bar, no "Compiling" messages, etc.). Is it at all possible to process both stderr and stdout at the same time?

Another concern is that delaying reading stderr could potentially deadlock. It's not too hard to generate enough data on stderr to fill the pipe buffer (particularly on platforms with smaller buf sizes). For example, running ./x.py test src/tools/cargo -v caused it to deadlock.

If you run with something like --nocapture, then it panics because it doesn't get something that looks like JSON. Would it maybe be possible for it to ignore lines that aren't JSON?

[pietroalbini]

Because it delays writing the stderr till the end. That can make it difficult to see which test suite is running at any one time. It also removes any sense of progress, as you just see it hang while cargo is building things (no progress bar, no "Compiling" messages, etc.). Is it at all possible to process both stderr and stdout at the same time?

Another concern is that delaying reading stderr could potentially deadlock. It's not too hard to generate enough data on stderr to fill the pipe buffer (particularly on platforms with smaller buf sizes). For example, running ./x.py test src/tools/cargo -v caused it to deadlock.

I made the change to show the standard error only at the end because without it the message compiletest displays when something fails gets interleaved with the failure message. I agree with you that doesn't work, I'll try a different approach.

If you run with something like --nocapture, then it panics because it doesn't get something that looks like JSON. Would it maybe be possible for it to ignore lines that aren't JSON?

Right, forgot about --nocapture 😅 I'll do that.

[pietroalbini]

So, to reiterate the problem with stderr, it was that compiletest emits a message at the end of a failing run to stderr, and that message would be always interleaved. The solutions that came to mind were:

1. Capture the standard error and show it at the end. This caused the problems Eric rightfully pointed out.
2. Spawn a separate thread that re-prints the captured standard error as it's outputted by the process, but have both the renderer and the stderr lock a mutex whenever they write. This would fully solve the problem, but by capturing Cargo doesn't color the messages anymore, and I'm not aware of any easy way to have a piped stream pretend to be a tty.
3. Change compiletest to emit a special {"type":"compiletest_message","message":"foo"} instead of foo when --json is passed. This works, as the message would be displayed by the rendered, but it feels unelegant.
4. Change compiletest to use println!() instead of eprintln!() to print that message. With the change of handling non-JSON stdout, this has the same effect as 3. but in a cleaner way.

I went with option 4., let me know if you want a different approach to be used or if there are approaches I didn't consider.

[bjorn3]

An alternative to option 4 is to redirect stdout and stderr to the same pipe or file.

[pietroalbini]

Wouldn't that have the same problem as option 2 (losing colors)?

[bjorn3]

Right. Unless you did use a pseudo terminal, but that is not easily portable to Windows.

[Mark-Simulacrum]

We only lose colors on the " Running tests/ppc.rs (obj/build/x86_64-unknown-linux-gnu/stage1-rustc/x86_64-unknown-linux-gnu/release/deps/ppc-8d20debf1e8d2487)", right? Or on both that and test output? I feel like that line not being colored is.. fine, but then I typically don't find colors very useful anyway...

[pietroalbini]

@Mark-Simulacrum we would lose:

• Color on the "Running tests/pcc.rs)" line
• Color on the "Compiling rustc_data_structures" lines
• The Cargo progress bar for compilation

[ehuss]

Overall it looks like this should work.

It seems unfortunate to need to write such a large amount of code for rendering. I'm wondering if an alternate solution would be to extend --logfile to contain the information you want. I realize that would be a more difficult change to make, but perhaps something to pursue later.

To support that, I think there would need to be some mechanism to indicate the format for the logfile. I'm not sure if that is just the combination of --format and --logfile.

Another thing that would need to be addressed is having some sort of templated filename. Right now, --logfile will overwrite the file. That is a problem for running cargo test on something that runs multiple tests (like multiple integration tests, or something with doctests). Somehow one would need to be able to map the file to the kind of test being run.
(Or have --logfile extend the file, and have extra information about what is being run.)

[bors]

⌛ Testing commit aacbd86 with merge 6667682...

[bors]

☀️ Test successful - checks-actions
Approved by: Mark-Simulacrum
Pushing 6667682 to master...

[rust-timer]

Finished benchmarking commit (6667682): comparison URL.

Overall result: ❌ regressions - no action needed

@rustbot label: -perf-regression

Instruction count

This is a highly reliable metric that was used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	0.4%	[0.3%, 0.4%]	2
Regressions ❌ (secondary)	-	-	0
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	0.4%	[0.3%, 0.4%]	2

Max RSS (memory usage)

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	1.3%	[0.8%, 1.8%]	2
Regressions ❌ (secondary)	-	-	0
Improvements ✅ (primary)	-1.4%	[-3.9%, -0.4%]	5
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	-0.6%	[-3.9%, 1.8%]	7

Cycles

Results

This is a less reliable metric that may be of interest but was not used to determine the overall result at the top of this comment.

	mean	range	count
Regressions ❌ (primary)	0.5%	[0.4%, 0.6%]	4
Regressions ❌ (secondary)	-	-	0
Improvements ✅ (primary)	-	-	0
Improvements ✅ (secondary)	-	-	0
All ❌✅ (primary)	0.5%	[0.4%, 0.6%]	4