Provide better diagnostics for why crates are rebuilt

[alexcrichton]

Right now Cargo can sometimes choose to recompile crates for surprising reasons, but it has lots of information internally to inform users as to why crates are recompiling. It'd be great to expose all this information!

Currently the best way to get this information is:

CARGO_LOG=cargo::core::compiler::fingerprint=trace cargo build

but then you have to wade through a bunch of other logging output. It'd be best if cargo would automatically do this on -v. Something like "recompiling crate foo because: ...". Maybe even -vv.

[jwilm]

but then you have to wade through a bunch of other logging output.

Adding such debug information to -v or -vv would result in even more log output to parse through in comparison with that RUST_LOG setting. A separate flag might be nicer to get only the rebuild diagnostics.

[davidbarsky]

I'm opposed to hiding that information behind a flag—in particular, the issue I had in #3067 would’ve been noticed far sooner. A (relatively) rare event like full recompilation of a dependency should—in my amateurish opinion—be communicated to the user as quickly as possible, and I think the regular cargo build output is a good place to put it.

Caveat: I am ignorant of most of cargo is designed.

[alexcrichton]

@davidbarsky yeah that sounds reasonable to me. We try to keep Cargo's UI pretty tight to ensure that you're not inundated with output, but perhaps we could do something like print Recompiling instead of Compiling with a small snippet of a reason at one end. Then if you pass -v we could print more information about why something is being recompiled.

[davidbarsky]

@alexcrichton Thanks Alex! Got a quick question though: wouldn’t passing -v only show the status for the currently executing build, not previous one? On other hand, a user might not care why a previous build recompiled, only if the build keeps recompiling.

[alexcrichton]

It's true yeah, -v may be too late in some situations. For debugging though it could be useful?

[jwilm]

Whenever I've encountered a recompiling issue it's usually very easy to reproduce, and opting into extra info via -v for debugging would be fine. If it's a one time issue and -v would be too late, is it really a problem?

[davidbarsky]

@alexcrichton @jwilm: Yep, I think you’re both right. Viewing information for a previous, one-off build is would probably take a lot of work and isn’t a particularly useful feature to have.

[RalfJung]

FWIW, I am semi-regularly mystified by why cargo rebuilds something -- sometimes just on CI so I have little chance of debugging, like here in line 130 where even though it just built Miri, a cargo install triggers a rather costly rebuild. (This rebuild doesn't happen on Linux/macOS, to make things even more strange.) ./x.py test --stage 0 src/tools/miri also does some odd unexpected rebuilds. And there is rust-lang/miri#1410.

Having some way of letting cargo tell me the reasons would be quite amazing.

[ehuss]

Having some way of letting cargo tell me the reasons would be quite amazing.

How would that work on CI? You can display the reasons today using the environment variable mentioned above. I have made some improvements lately so that it displays more relevant information.

I can see some improvements:

• "After the fact reporting." Often a rebuild happens at an unexpected time, and by then it is too late to enable logging. If it isn't easily reproducible, this makes it difficult. If Cargo could save to disk the reason, then some command could be used to ask Cargo to display "why did you just rebuild x?". I'm not sure if we can implement this efficiently, but we are already saving a JSON structure for each package, so it seems feasible.
• Reasons are too verbose. The logging right now is extremely verbose, because it covers every possible scenario on every package, and some of the information isn't available in one place (the mtime decision is made in different locations and different times). This could definitely be improved, but there are situations that are unexpected (weird filesystems or cargo bugs) where today the "spew tons of information" is the only way to debug them. Also, we only track dependencies as a hash, so if a package is rebuilt because a dependency is out-of-date, all we can say is "some dependency was outdated". Tracking more information is costly.

But if this is CI, how would you go about diagnosing it? What kind of UI would you like?

[RalfJung]

How would that work on CI? You can display the reasons today using the environment variable mentioned above. I have made some improvements lately so that it displays more relevant information.

Well it's not interactive so the information has to basically be spot-on and not require further experimentation. That's what makes CI harder.

I have made some improvements lately so that it displays more relevant information.

"it" is RUST_LOG=cargo::ops::cargo_rustc::fingerprint? I just tried that locally and it doesn't show anything.

But if this is CI, how would you go about diagnosing it? What kind of UI would you like?

Something like cargo build -v or so -- not having seen the RUST_LOG output for cargo yet but having seen it for other projects, it's usually full of information that is relevant to developers but not users. Though even cargo -v already prints many things that are not relevant for debugging rebuilds, so maybe it should be a separate flag. And then I'd imagine it would write something like

   Recompiling atty v0.2.14 because feature flag X got added/removed
   Recompiling aho-corasick v0.7.10 because environment variable Y changed
   Recompiling directories v2.0.2 because file Z changed

[ehuss]

just tried that locally and it doesn't show anything.

Oh, sorry, the original comment was out of date (being nearly 4 years old). I updated it:

CARGO_LOG=cargo::core::compiler::fingerprint=trace cargo build

Yea, -v can be noisy. It would be nice if there is a more granular way to indicate which extra information you want to display. CARGO_LOG sorta fills that, but it is difficult to use. I've thought about adding explicit log targets to make it easier (CARGO_LOG=fingerprint). I'm not sure if that's good enough, or if there should be something explicit from the command-line.

[RalfJung]

Ah, with CARGO_LOG I am getting some output, thanks. I'll play around with this to see if I can make any sense of it.

I'm a little afraid using it on CI will just blow to an insurmountable amount of logs.^^