Show long-running tests in progress, even when multithreaded

[sourcefrog]

Hi,

It bothered me that in Rust by default, if a test takes a long time, you just see the cursor on a blank line with no indication what's running.

This was previously discussed in #2873 (comment) and #30047 amongst others. Those are closed as infeasible, but actually we can do a lot better.

In previous discussion was concluded nothing could be done short of a prettier full-screen UI that can update multiple status lines. I think that'd be a great idea, but it's a larger change and anyhow seems like the dependency on a fancy UI library might be a problem for core libraries.

However it seems to me we can still do better in line-at-a-time output, by showing at least the name of one test that's currently running, even if others are still running in the background.

In my tests, with this change, we get the key behavior that a slow test will show

test slow_thing ...

until it completes, and it does align with the tests I expect are slow.

[rust-highfive]

r? @withoutboats

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

[sourcefrog]

This could probably be further cleaned up by separating the printing from the counting in separate observers, but I thought I'd keep this small and get some early feedback.

[kennytm]

Thanks for the PR! We’ll periodically check in on it to make sure that @withoutboats or someone else from the team reviews it soon.

[carols10cents]

review ping for you @withoutboats! pinging you on IRC too!

[kennytm]

Review ping for you @withoutboats! Also cc @rust-lang/dev-tools.

[alexcrichton]

Thanks @sourcefrog! @sourcefrog does this mean, though, that a test name could be printed, a bunch of others finish, and no output happens while we're waiting on that one test to finish?

[sourcefrog]

Hi @alexcrichton

Yes, that's right, if it prints the name of A and while A is running, B, C and D also complete, you'll eventually see it says 'ok' for A, and then immediately also prints B, C, and D.

This actually works surprisingly very well for what I see as the key use: showing you what tests are keeping you waiting - so you can either go and improve them, or at least so you have some sense that it's actually working and not hung. The tests that linger on the screen are likely to be the slow tests. Psychologically I think it's a big improvement.

I'll try to put a screencast up later which may be more convincing.

What it doesn't do, as you note, is to tell you what all of the slow tests are, in case perhaps you're going to do a project of speeding them up. Doing that well probably requires a different output mode where it prints the timing (and maybe cpu usage) per test, perhaps to a CSV output, or just at the end of the line. I think some Python test runners do this. I think it's complementary to this change.

The other thing this doesn't do is tell you all of the tests in flight at the moment, which I also agree would be nice. I can imagine how you could do that in a fullscreen text mode, perhaps using https://github.com/mitsuhiko/indicatif, although that may have challenges wrt adding those libraries as dependencies of the standard library.

Perhaps a good way to avoid excessive stdlib dependencies it would be to allow external packages to provide a test ui that cargo test calls. Perhaps it should be done by having cargo test emit a stream of subunit events (https://github.com/testing-cabal/subunit/) that the test runner displays.

I don't at the moment see a great way to show multiple tests in flight in line-at-a-time output, particularly considering it might be going into an editor buffer where even repainting the current line might not work. We could show separate lines for 'A started', 'B started', 'B finished', 'A finished' but that seems much less readable.

So overall: yes but I think it's still a big improvement.

[alexcrichton]

Yeah in general I think we can have a lot of UI improvements to libtest, but I'd also personally at least prefer to avoid regressing any existing workflows. For example I'd consider it quite important to print out successful tests as these are often the only logs you get when running tests on CI for example. Given mysterious logs knowing where not to look is just as important as knowing where to look, so I'd personally prefer to not have this sort of behavior by default.

If we're ambitious I think there's a lot we could do with \r though as from what I've seen that's pretty universally supported in terminals. That way we could print "Running ..." and then "backspace over it" when a test finishes and then update the status later.

[sourcefrog]

Hi Alex,

Just to be clear, this will print out successful tests, but they can be delayed a bit.

I think the main case this can make a difference is if the test process suddenly aborts without getting to flush its output. I can imagine how that could happen perhaps due to a Rust bug or the CI infrastructure timing it out.

So with this PR as it is you would lose information on what already finished, but you would get some information about what was still running, which I would have guessed is equally interesting in the case the runner process crashes? If you suspect one of the tests is causing the runner process to crash, I'd guess you need to run it in singlethreaded mode to narrow it down? Of course you'll have much more experience with such things in Rust than me.

Anyhow, all that aside, yes, I can try an alternative PR that uses \r.

[kennytm]

Ping from triage everyone!

r? @alexcrichton (since @withoutboats has never commented on this PR).

@alexcrichton what do you think about OP's reply at #46990 (comment)?

@sourcefrog have you got a chance to try the \r suggestion?

[sourcefrog]

Haven't tried that yet but I will. I can withdraw this if you don't want it in the current form.

…

On Jan 24, 2018 3:00 AM, "kennytm" ***@***.***> wrote: Ping from triage everyone! r? @alexcrichton <https://github.com/alexcrichton> (since @withoutboats <https://github.com/withoutboats> has never commented on this PR). @alexcrichton <https://github.com/alexcrichton> what do you think about OP's reply at #46990 (comment) <#46990 (comment)>? @sourcefrog <https://github.com/sourcefrog> have you got a chance to try the \r suggestion? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#46990 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAVI88xX5epxOHjnf8LsOrqefCOFs510ks5tNw1IgaJpZM4RMB5I> .

[alexcrichton]

@sourcefrog yeah it definitely makes sense that the output is just delayed a bit, but for me personally at least I'd prefer that we don't hide output via \r if possible

[kennytm]

Ping from triage again!

@alexcrichton if I understand #46990 (comment) correctly it means not doing \r is better? And given #46990 (comment), what OP should do instead is place the new behavior (this PR) behind a command line argument?

[alexcrichton]

Er sorry no to clarify I'd personally prefer to not land this PR as-is as it hides what I feel is too much information by default. Using something like \r would solve that problem though because libtest can "erase" what it previously wrote with a successful status. That way we can, at all times, have a "pending test" printed to the console in addition to all completed tests.

[sourcefrog]

I'll look into \r in a separate PR.