rust-lang / cargo

The Rust package manager
https://doc.rust-lang.org/cargo
Apache License 2.0
12.74k stars 2.42k forks source link

Console output should better reflect the build process #8889

Open nnethercote opened 3 years ago

nnethercote commented 3 years ago

Describe the problem you are trying to solve

The console output can be misleading about what's happening in the build. Having lots of sequential Compiling <crate> lines makes it seem like compilation is serial, and if a slow-building crate X starts building just before a fast-building crate Y, you'll probably think that Y is the slow-building crate. (I was misled in this way about build times of different crates within rustc for a long time.)

The progress bar helps with this, because it shows which crates are currently being built... but only if you have a sufficiently wide terminal. If you have 80 chars you don't see them at all. If you have 100 chars you might see one or two or three, but any crate with a long name greatly reduces the effectiveness.

Also, linking isn't shown. This means people often blame the compiler for slowness when it's the linker's fault.

Describe the solution you'd like

  1. Instead of printing Compiling <crate> when a crate starts building, print Compiled <crate> in X.YYs. That would avoid the problem where slowness to build is blamed on the wrong crate. This is a change of tense in the message, but Cargo already mixes present and past tenses, e.g. with Downloaded <crate> and Downloaded2 3 crates (78.7 KB) in 1.03s messages.

  2. Shrink the width of the progress bar, so the crates being built can be seen even on narrow terminals.

  3. Show linking as a distinct step, including the time it took, e.g. `Linked in X.YYs".

Notes

My motivation here was comparing console output (which is moderately useful) to -Ztimings output (which is amazing), and trying to make the former a bit more like the latter.

See also

nnethercote commented 3 years ago

2. Shrink the width of the progress bar, so the crates being built can be seen even on narrow terminals.

8892 does this.

ehuss commented 3 years ago

I don't think it is currently possible to show link time as a separate stat, since rustc does compilation+linking together. It might be possible to have rustc spit out a JSON message when it starts linking, and Cargo could catch that to start a new timer. There might be a tiny delay, but I suspect not enough to affect the timing in a meaningful way. I think that would be useful (at least for -Ztimings). Would need to ask the compiler team what they think about adding instrumentation like that.

nnethercote commented 3 years ago

Maybe Cargo could output "Compiling and linking" (or "Compiled and linked") instead? Less precise, but still clearer than the current output.

alexcrichton commented 3 years ago

The intention of the current progress bar was to give an indicator as to what's currently compiling so we don't have to just read the last line and blame that (ideally), but it's true that we never got back to updating the console output otherwise. I'd be a bit wary of indicating the compile time of each crate individually because that could add up to a lot of noise in the current output scheme.

All that being said though, I think it's high time we completely revamp Cargo's output. Even one-short-line-per-package feels unnecessarily verbose today. I'd sort of prefer if we could have the progress bar we currently have but have maybe at most 4-5 other lines indicating "these were the slowest crates to compile" or something like that. Then when Cargo finishes it could erase the output or leave it all there. (or something like that).

Basically I think the current output has gotten us this far but it could benefit from a complete overhaul in addition to smaller tweaks.

joshtriplett commented 3 years ago

@ehuss We've talked about, for other reasons, separating compilation and linking: https://github.com/rust-lang/rust/issues/64191

If we do that in rustc, cargo should use that, and could then reflect that in its output.

dtolnay commented 3 years ago

I think it's high time we completely revamp Cargo's output. Even one-short-line-per-package feels unnecessarily verbose today.

Sharing two recordings for possible inspiration. Both of these build systems' outputs are designed around accurately surfacing where the most time is getting spent in builds with (extremely) high parallelism. The currently running longest running jobs are always at the top.


Peek 2021-02-17 21-01

Peek 2021-02-17 21-02

ehuss commented 3 years ago

Thanks @dtolnay for sharing those. I'm not too familiar with what kind of terminal detection and support is necessary to be able to create multi-line progress indicators like that, especially across a myriad of platforms. Cargo's current progress bar is extremely primitive, which makes it a little easier to maintain, but is much more limiting.

I think it would be great to improve the output, I just hope it doesn't require pulling in large dependencies, or require heroic efforts to get it to work across terminals. Cygwin/msys on Windows has been particularly hard to support, since Cargo doesn't live in the Cygwin universe, it is limited on what it can do.

I'm also curious how warnings and errors get displayed. One problem I struggled with in the current progress bar implementation is that it has to clear the progress bar in order to display a message (and scroll the output up), and then redisplay the progress bar. This causes severe flickering on some terminals (particularly on Windows). I'm curious how buck and bazel and other tools handle that.

camsteffen commented 3 years ago

Minor suggestion. The list of crates in the Building line should match the order that they are printed in the Compiling lines. That is, the one that has been running the longest should be first, IIUC.

arcuru commented 2 years ago

I am interested in working on this, and have already created a hacky prototype build using crossterm that is heavily influenced by buck/bazel. See the recording below.

@alexcrichton @ehuss @dtolnay Since this is pretty old, could you confirm if you'd actually want to take this change? It's a decent chunk of work to do it properly so I don't want to spend too much time on it if you're no longer interested.

asciicast

dtolnay commented 2 years ago

If you are interested in something less hacky, check out https://github.com/facebookincubator/superconsole.

Here is some further inspiration from buck2, which uses superconsole for the UI. This is building the same crate as in your asciinema:

Peek 2022-07-20 01-32

bjorn3 commented 2 years ago

I did like to keep the history of crates that have been built already.

dtolnay commented 2 years ago

@bjorn3: in buck there is a buck log what-ran command for that purpose, which you'd run after the fact to find out information about the last invocation. I like something like that over filling the terminal with dozens to thousands of lines every time. It can also be convenient for scripting; flags for output format (json) and what information to include (timings, crate authors, licenses, number of warnings, ā€¦).

bjorn3 commented 2 years ago

That doesn't give you a history after you ran buck again, right? It also isn't possible at all to run that command if the build happened on CI. Also knowing which crates have already been compiled/are compiling helps when matching errors and warnings to the original crate as rustc diagnostics lack any indication of crate or package name.

dtolnay commented 2 years ago

That doesn't give you a history after you ran buck again, right?

I turned it off for the recording above, but in actual usage buck will print a URL as the first line of every build, which stays on screen after the build and you can access after the fact. See here where it says "Buck UI" at the top.

It also isn't possible at all to run that command if the build happened on CI.

CI does not use the same UI. The superconsole UI from https://github.com/rust-lang/cargo/issues/8889#issuecomment-1189982357 would obviously not be appropriate for CI. In buck's case, it detects CI (I'm not sure if via environment variables or just isatty) and switches to a simple one-line-per-action UI.

Also knowing which crates have already been compiled/are compiling helps when matching errors and warnings to the original crate as rustc diagnostics lack any indication of crate or package name.

One line per crate is not great for this either. The "Compiling" message for a particular crate can appear way above that crate's warnings in the case that "Compiling" was printed when the build script started building, which built without warnings, and only the library afterwards had warnings. I think there are better ways of addressing this consideration.

arcuru commented 2 years ago

I understand that bikeshedding for this type of UX change is inevitable, but I don't want to get caught up in that until we get a confirmation of whether or not this change is still desired.

Let me at least clarify the design ideas that I do have so it's a bit easier to envision. I'm of course open for the project leadership to have the final say on the design but my viewpoint is the following:

  1. I think it's important to retain a similar design language to the existing Cargo output, with minimal additions to add the extra bits of info that this new design would allow. We shouldn't be trying to match the "look" of these other build tools, instead we should borrow ideas for what information is useful and incorporate that into Cargo's UX.
  2. The extra info that we should be adding over the existing progress bar are a count/list of in progress tasks and timings for at least longer tasks. I think we should continue reporting at the same level of verbosity as current Cargo (one 'task' per crate) instead of breaking them out into individual actions like the buck example above, mainly to maintain compatibility with Cargo's current design language.
  3. We should drop the scroll of messages for normal interactive usage in favor of using the progress view only, as in my example above. If we do decide to keep them, they should be reporting of completed work instead of reporting the start of work like today. Reporting work start is the job of the progress bar.
  4. For warnings or errors from rustc, we should be able to capture the output and print a line like "Compiled XX with warnings:", followed by the warning message, once the crate has finished compiling. Those messages will be displayed above the progress bar and persist upon exit. That will fix the current issues we have with trying to associate the warning and error messages with the right crate, see #8977.
  5. The fallback output for "dumb" terminals or CI should be switched so that we report task completion + captured output at the same time. We already detect that and drop the progress bar in those cases.

Getting this to work will require a good amount of refactoring to centralize the output reporting. In brief, we have to pipe all the output to a single stateful progress indicator so that we can pretend that Cargo actually uses a single job queue. We'll need to do this so that we can have all of the output UX handled in the same centralized way and avoid the fragmentation that currently exists. I think doing this lets us present the user with the right mental model even if the underlying details don't quite match.

I would plan to do that work first, without any significant changes to the output UX, and then iterate on the design.

If there's a process that you would prefer is followed for a change of this magnitude, please let me know.

nnethercote commented 2 years ago

@patricksjackson I'm no Cargo expert, but I think everything you've written is reasonable and well thought out.

dtolnay commented 2 years ago

@patricksjackson I think the best way to make fast progress on the user interface design without overburdening the Cargo maintainers with reviews or Cargo users with an unstable experience is going to be by delegating the whole UI to a separate process.

Proposal:

That's it. We don't need to debate what information should appear in the UI or what the color and boldness and positioning of everything should be. We'll give the ecosystem 1–2 years to build a suite of great UI options with different tradeoffs, and then discuss how to import or fork one of them to become the out-of-the-box default UI for cargo.

We can kickstart folks by providing a skeleton crate called cargo-legacy-tui (with [[bin]] name = "cargo-tui") which exactly reimplements Cargo's current UI. Anyone interested can fork this and build a fancier experience atop it. Users can swap in any new UI by doing cargo install cargo-fancy-ui-of-your-choice (again assuming it provides [[bin]] name = "cargo-tui").

For debugging, or for cargo's test suite, something like ln -s /bin/cat ~/.cargo/bin/cargo-tui or ln -s /usr/bin/jq ~/.cargo/bin/cargo-tui is a cool trick.

arcuru commented 2 years ago

@dtolnay I'm confused by your suggestion. This feels like a more complicated solution to build that creates more work for the Cargo team and the community. Your proposed solution provides unclear value considering the community isn't asking for such a solution here, so a flexible solution is not useful. Can you clarify what value you see in this solution compared to my proposal? And what other similar tools find it useful to do something like this?

This issue has sat for multiple years with no interest, so I am proposing a straightforward solution both to implement and to utilize, that I'm willing to build.

dtolnay commented 2 years ago

Sure thing; I don't have confidence that iterating on the built-in cargo UI in the way you suggest would lead to the best result in the long term, as opposed to just a local optimum that is better on a few axes than the current UI, but otherwise even harder to iterate further and permanently suboptimal in comparison to state-of-the-art build tools.

Closing the gap between Cargo's current build UI and the state-of-the-art in build UI from other tools requires in my opinion bigger experimentation and bigger disruptive advancements than what it would make sense to iterate on in Cargo's own codebase. Performing those design iterations externally, in a way that Cargo users can easily install and provide feedback on without needing to fork all of cargo, will arrive at a better outcome. The reasons it will arrive at a better outcome are:

To the extent that you've suggested a straightforward solution, it's a solution to doing better than Cargo's current UI but I don't see it as a solution to matching or advancing the state of the art.

arcuru commented 2 years ago

Right. Thanks for clarifying.

I admit I'm very curious what useful, actionable information a "state-of-the-art build UI" would present that isn't already presented by the likes of buck/bazel, but I'm happy to let someone else figure that out. The only things I can think of are largely aesthetic choices, like better representations of the DAG.

I continue to feel that the best way forward, balancing the apparent level of interest from the community and ROI for the Cargo team, lies in my suggested path. I think it's perfectly fine for Cargo's TUI to move towards a local maxima representing the latest in "SOTA build UIs"

I may continue to work on a more complete patchset with my proposed changes to shop around, but it'll stay on my backburner unless I run out of other projects or the Cargo team indicates interest.

dtolnay commented 2 years ago
epage commented 1 year ago

Summary of discussion so far (with some of my own ideas thrown in)

Some interests of what to include

Implementation

epage commented 1 year ago

We discussed this briefly in the cargo team meeting. A concern raised about the fancy superconsole output is how universally the ansi escape codes needed are supported and how well we can detect and fallback in that situation.

Currently, cargo skips progress bars for quiet, CI, or if TERM=dumb (code). The CI check was added in #6281 in response to starting to use an ansi escape code in #6233. Oddly, it doesn't check if its writing to a TTY...

Python's tqdm seems only check if its writing to a TTY (code)

As for Rust (generally in order of monthly downloads)

Depending on how fancy we get, unicode detection might become important

For reference on all of this, cargo nextest is using indicatif and supports-unicode

I got a tip to check fish. It seems to rely on terminfo with some hacks for Mac and Midnight Command (code)

On Discord, someone had this to say:

i've done a lot of this. it's kind of a mess honestly. for anything advanced you need a bunch of heuristics, terminfo parsing, and DEC queries. that said for basic progress bar detection you should be able to just get by on terminfo parsing + heuristics to detect when terminfo might be lying in general something like terminfo parsing + "treat any TERM with xterm in it as fairly capable" + "give up on any terminfo with delay expressions (e.g. $)" is probably reasonable

bjorn3 commented 1 year ago

Another disadvantage of superconsole is that it breaks scrolling up to see the previously built crates (and in case of -v their rustc invocation) It also likely doesn't work well with CARGO_LOG.

epage commented 1 year ago

My expectation is that in using something like superconsole, we would stop listing all of the crates that built but that we would, like buck, provide a command to see what was previously built which would also help with #2904.

I think it would also be reasonable to revert back to the current progress system with -v.

Byron commented 1 year ago

I just wanted to add that prodash is merely used, by gix, as an interface to transmit hierarchical progress in potentially long-running operations. Even though it provides its own renderers I don't think they are suitable here so I presume even if cargo gets improved progress output, we would still stick with a translation layer like it's currently implemented, to display git specific progress.

prodash renderers definitely won't set the bar for understanding their terminal environment either, and when writing it "works for me" was good enough. It does respect NO_COLOR though.

epage commented 5 months ago

btw zig has made their output more dynamic and the HN thread has some discussion on the trade offs: https://news.ycombinator.com/item?id=40519976

weihanglo commented 4 months ago

btw zig has made their output more dynamic and the HN thread has some discussion on the trade offs: news.ycombinator.com/item?id=40519976

A slightly different output style from the Nix community: https://github.com/maralorn/nix-output-monitor. (Also print a dependency graph.)