Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rustbuild: Both stage0 and stage1 std are rebuilt spuriously #68149

Closed
petrochenkov opened this issue Jan 12, 2020 · 33 comments · Fixed by #68298
Closed

rustbuild: Both stage0 and stage1 std are rebuilt spuriously #68149

petrochenkov opened this issue Jan 12, 2020 · 33 comments · Fixed by #68298
Labels
C-bug Category: This is a bug. T-bootstrap Relevant to the bootstrap subteam: Rust's build system (x.py and src/bootstrap)

Comments

@petrochenkov
Copy link
Contributor

I'm not sure when exactly it happens, but it reproduces roughly like this:

  • Rebase my working branch on upstream/master.
  • Run ./x.py test --stage 1 src/test/ui --test-args mytest, the build starts from stage0 std or later and succeeds.
  • Run ./x.py test --stage 1 src/test/ui --test-args mytest again, should be a trivial build, but the build starts from stage0 std or stage1 std again and succeeds.
  • Run ./x.py test --stage 1 src/test/ui --test-args mytest again, trivial build happens.

The target is x86_64-pc-windows-gnu.
The issue exists for several weeks, so it's a regression.
cc @Mark-Simulacrum

@petrochenkov petrochenkov added T-bootstrap Relevant to the bootstrap subteam: Rust's build system (x.py and src/bootstrap) C-bug Category: This is a bug. labels Jan 12, 2020
@petrochenkov
Copy link
Contributor Author

petrochenkov commented Jan 12, 2020

Reproduction script:

./x.py test --stage 1 src/test/ui --test-args mytest
rm -rf build/x86_64-pc-windows-gnu/{stage1*,stage0-sysroot}
./x.py test --stage 1 src/test/ui --test-args mytest
./x.py test --stage 1 src/test/ui --test-args mytest -vvvvvv

You might have to run it multiple times to cause the spurious rebuild in the last command.

@petrochenkov
Copy link
Contributor Author

For some reason backtrace v0.3.40 is getting recompiled:

Building stage1 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
running: "C:\\msys64\\home\\we\\rust\\build\\x86_64-pc-windows-gnu\\stage0\\bin\\cargo.exe" "build" "-Zconfig-profile" "--target" "x86_64-pc-windows-gnu" "-Zbinary-dep-depinfo" "-j" "8" "-v" "-v" "-v" "-v" "-v" "--release" "--features" "panic-unwind backtrace compiler-builtins-c" "--manifest-path" "C:\\msys64\\home\\we\\rust\\src/libtest/Cargo.toml" "--message-format" "json-render-diagnostics"
       Fresh cc v1.0.49
       Fresh core v0.0.0 (C:\msys64\home\we\rust\src\libcore)
       Fresh autocfg v0.1.6
       Fresh rustc-std-workspace-core v1.99.0 (C:\msys64\home\we\rust\src\tools\rustc-std-workspace-core)
       Fresh compiler_builtins v0.1.22
       Fresh libc v0.2.66
       Fresh cfg-if v0.1.8
       Fresh alloc v0.0.0 (C:\msys64\home\we\rust\src\liballoc)
       Fresh backtrace-sys v0.1.32
       Fresh rustc-demangle v0.1.16
       Fresh panic_abort v0.0.0 (C:\msys64\home\we\rust\src\libpanic_abort)
       Fresh rustc-std-workspace-alloc v1.99.0 (C:\msys64\home\we\rust\src\tools\rustc-std-workspace-alloc)
       Fresh unwind v0.0.0 (C:\msys64\home\we\rust\src\libunwind)
   Compiling backtrace v0.3.40
       Fresh hashbrown v0.6.2
       Fresh panic_unwind v0.0.0 (C:\msys64\home\we\rust\src\libpanic_unwind)

@petrochenkov
Copy link
Contributor Author

cc @alexcrichton

@Mark-Simulacrum
Copy link
Member

I think @eddyb was hitting this at some point as well, though we weren't able to determine quite why.

@petrochenkov petrochenkov added regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. and removed regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. labels Jan 12, 2020
@petrochenkov
Copy link
Contributor Author

petrochenkov commented Jan 12, 2020

I haven't encountered these rebuilds before, but recently (since December?) they happen quite often, like every second or third build, and that's pretty inconvenient given the long builds.

Perhaps something changed in backtrace itself?

@Mark-Simulacrum
Copy link
Member

I don't think we've changed backtrace itself recently.

It would perhaps be handy to check if this still happens before 87540bd (which changed how/when we clear out std's target directory). However, I don't expect it would have, as that would cause all of std to be rebuilt, not just backtrace. Maybe backtrace is unique in being a dependency of both std and the compiler (for example?). I'm not sure what could be causing this odd behavior :/

@petrochenkov
Copy link
Contributor Author

I'm pretty sure the rebuilds appeared before 87540bd (and I hoped that PR would fix them, but it didn't).

@petrochenkov
Copy link
Contributor Author

I suspect #67077 to be the cause, at least based on timing.

@mati865
Copy link
Contributor

mati865 commented Jan 12, 2020

I've been hitting similar (this?) issue with x86_64-pc-windows-gnu when doing dist builds. Somehow it disappeared whenever I ran build before dist so I kept doing that as the workaround.

@Mark-Simulacrum
Copy link
Member

Hm, so #67077 in theory at least wouldn't have affected backtrace specifically, I think, though there may have been knock on effects.

One thing that might be helpful is getting a log with CARGO_LOG=cargo::core::compiler::fingerprint=info on the spurious rebuild (to know why Cargo thinks it needs to rebuild it).

@petrochenkov
Copy link
Contributor Author

Update: this reproduces on ./x.py build --stage 0 src/libstd too (which runs much quicker and involves less moving parts), just got a backtrace rebuild after a clean build this way.

I'll try CARGO_LOG=cargo::core::compiler::fingerprint=info.

@petrochenkov
Copy link
Contributor Author

Reproduced on ./x.py test --stage 1 src/test/ui --test-args mytest (#68149 (comment)) with CARGO_LOG=cargo::core::compiler::fingerprint=info:

Building stage1 std artifacts (x86_64-pc-windows-gnu -> x86_64-pc-windows-gnu)
running: "C:\\msys64\\home\\we\\rust\\build\\x86_64-pc-windows-gnu\\stage0\\bin\\cargo.exe" "build" "-Zconfig-profile" "--target" "x86_64-pc-windows-gnu" "-Zbinary-dep-depinfo" "-j" "8" "-v" "-v" "-v" "-v" "-v" "--release" "--features" "panic-unwind backtrace compiler-builtins-c" "--manifest-path" "C:\\msys64\\home\\we\\rust\\src/libtest/Cargo.toml" "--message-format" "json-render-diagnostics"
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] stale: changed "C:\\msys64\\home\\we\\rust\\build\\x86_64-pc-windows-gnu\\stage1-std\\x86_64-pc-windows-gnu\\release\\deps\\libcore-2b12e3ff20349daa.rlib"
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]           (vs) "C:\\msys64\\home\\we\\rust\\build\\x86_64-pc-windows-gnu\\stage1-std\\x86_64-pc-windows-gnu\\release\\.fingerprint\\backtrace-f79483b0a3bcfa52\\dep-lib-backtrace-f79483b0a3bcfa52"
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]                FileTime { seconds: 13223331039, nanos: 670850900 } != FileTime { seconds: 13223331039, nanos: 689869600 }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for test v0.0.0 (C:\msys64\home\we\rust\src\libtest)/Build/Target { ..: lib_target("test", ["dylib", "rlib"], "C:\\msys64\\home\\we\\rust\\src\\libtest\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for getopts v0.2.21/Build/Target { ..: lib_target("getopts", ["lib"], "C:\\Users\\we\\.cargo\\registry\\src\\github.com-1ecc6299db9ec823\\getopts-0.2.21\\src\\lib.rs", Edition2015) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for rustc-std-workspace-std v1.99.0 (C:\msys64\home\we\rust\src\tools\rustc-std-workspace-std)/Build/Target { ..: lib_target("rustc-std-workspace-std", ["lib"], "C:\\msys64\\home\\we\\rust\\src\\tools\\rustc-std-workspace-std\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for std v0.0.0 (C:\msys64\home\we\rust\src\libstd)/Build/Target { ..: lib_target("std", ["dylib", "rlib"], "C:\\msys64\\home\\we\\rust\\src\\libstd\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for backtrace v0.3.40/Build/Target { ..: lib_target("backtrace", ["lib"], "C:\\Users\\we\\.cargo\\registry\\src\\github.com-1ecc6299db9ec823\\backtrace-0.3.40\\src\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for unicode-width v0.1.6/Build/Target { ..: lib_target("unicode-width", ["lib"], "C:\\Users\\we\\.cargo\\registry\\src\\github.com-1ecc6299db9ec823\\unicode-width-0.1.6\\src\\lib.rs", Edition2015) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for proc_macro v0.0.0 (C:\msys64\home\we\rust\src\libproc_macro)/Build/Target { ..: lib_target("proc_macro", ["lib"], "C:\\msys64\\home\\we\\rust\\src\\libproc_macro\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint] fingerprint error for term v0.0.0 (C:\msys64\home\we\rust\src\libterm)/Build/Target { ..: lib_target("term", ["lib"], "C:\\msys64\\home\\we\\rust\\src\\libterm\\lib.rs", Edition2018) }
[2020-01-12T19:31:02Z INFO  cargo::core::compiler::fingerprint]     err: current filesystem status shows we're outdated
       Fresh cc v1.0.49
       Fresh core v0.0.0 (C:\msys64\home\we\rust\src\libcore)
       Fresh autocfg v0.1.6
       Fresh rustc-std-workspace-core v1.99.0 (C:\msys64\home\we\rust\src\tools\rustc-std-workspace-core)
       Fresh compiler_builtins v0.1.22
       Fresh libc v0.2.66
       Fresh cfg-if v0.1.8
       Fresh alloc v0.0.0 (C:\msys64\home\we\rust\src\liballoc)
       Fresh rustc-demangle v0.1.16
       Fresh backtrace-sys v0.1.32
       Fresh panic_abort v0.0.0 (C:\msys64\home\we\rust\src\libpanic_abort)
       Fresh rustc-std-workspace-alloc v1.99.0 (C:\msys64\home\we\rust\src\tools\rustc-std-workspace-alloc)
       Fresh unwind v0.0.0 (C:\msys64\home\we\rust\src\libunwind)
   Compiling backtrace v0.3.40
       Fresh hashbrown v0.6.2
       Fresh panic_unwind v0.0.0 (C:\msys64\home\we\rust\src\libpanic_unwind)

@ehuss
Copy link
Contributor

ehuss commented Jan 12, 2020

I was able to reproduce this once, but I'm having trouble reproducing it again. When I did reproduce it, I noticed that the dep-lib-backtrace included libcore-*.rlib. That is not normal, and I think points to a race condition with the libcore rlib getting emitted at just the wrong time. I suspect it is due to pipelining and maybe -Zbinary-dep-depinfo. I'm still trying to figure that out.

@Mark-Simulacrum
Copy link
Member

binary-dep-depinfo should not include backtrace into libcore, I think, since we don't pass --extern backtrace to libcore (nor is there an implicit "sysroot" dep from libcore; core depends on nothing).

I don't know why we're including dep-lib-backtrace in the libcore dep file though, that does sound like a bug. I guess this is then likely an upstream bug in some sense? I think leaving it here for tracking at least for now makes sense though.

@ehuss
Copy link
Contributor

ehuss commented Jan 12, 2020

It's the other way around. backtrace's dep-info file noted a dependency on libcore, which is normal. Normally it should only list the .rmeta file, but when I saw it, it also included the libcore.rlib file. That normally shouldn't happen because the libcore codegen step takes such a long time (normally finishes after backtrace is finished).

I'm not too familiar with the compiler, so it's a little slow for me to figure out. I seem to recall being told that writing the .rlib file is not done in an atomic fashion, is that correct? Perhaps writing it can take a long time, and backtrace started after the libcore.rlib was created and finished running before the libcore.rlib was done? I also seem to recall that there are protections in rustc to deal with partially written rlib files, but I'm not sure how that is accomplished (are there checksums?).

@Mark-Simulacrum
Copy link
Member

We currently emit a dependency on both the rmeta and rlib files (presuming they were found during building, I guess?) with binary-dep-depinfo. That might be in error! I did so as the most pessimistic option when initially adding that feature, but perhaps I was too eager in pulling in dependencies.

If I'm understanding correctly, that may mean that if libcore's codegen completes before backtrace is built, we'll pull in the libcore rlib as a dependency of backtrace, and then when backtrace is checked for freshness in the future, we'll notice that it's actually been built before the rlib (which we finished writing after libbacktrace started).

Is there ever a case where there's a dependency on rlibs directly? Maybe we should only emit rmeta/dylib filepaths in binary-dep-depinfo?

@petrochenkov
Copy link
Contributor Author

For reference, here's what I have in that dep-lib-backtrace-f79483b0a3bcfa52 file (with NUL bytes removed):

x86_64-pc-windows-gnu\release\deps\librustc_std_workspace_core-6405c2bc1ac2eb0f.rmeta
x86_64-pc-windows-gnu\release\deps\libcore-2b12e3ff20349daa.rlib
x86_64-pc-windows-gnu\release\deps\libcore-2b12e3ff20349daa.rmeta
x86_64-pc-windows-gnu\release\deps\libcompiler_builtins-b7b098ff94e5d507.rmeta
x86_64-pc-windows-gnu\release\deps\librustc_demangle-82d903482b6d7f70.rmeta
x86_64-pc-windows-gnu\release\deps\libcfg_if-08466b4601c0096d.rmeta
x86_64-pc-windows-gnu\release\deps\libbacktrace_sys-fcb8e997781d264b.rmeta
x86_64-pc-windows-gnu\release\deps\liblibc-9746d51efed770e0.rlib
x86_64-pc-windows-gnu\release\deps\liblibc-9746d51efed770e0.rmeta 

@Mark-Simulacrum
Copy link
Member

Hm, so it looks like in practice we read metadata from the first of the three that we find -- so in some sense, we don't actually depend on all three, but rather rlib/rmeta/dylib, in that order, when we're loading up dependency information.

I guess there's not really any tracking for which one we've used metadata from, but in practice, we should probably only emit one of these (probably rmeta/rlib/dylib, in that order) that we have set as the CrateSource.

@petrochenkov
Copy link
Contributor Author

Hm, so it looks like in practice we read metadata from the first of the three that we find -- so in some sense, we don't actually depend on all three, but rather rlib/rmeta/dylib, in that order, when we're loading up dependency information.

This is actually something that I wanted to try to change (#64882 (comment)) and read from the rmeta first.

@petrochenkov
Copy link
Contributor Author

Even if rmeta is used for reading metadata, rlib can still be used for reading object code, in that case both should indeed be in dependencies?
Perhaps cargo just timestamps the link time dependencies at the wrong time? (Earlier than necessary, together with rmeta.)

@ehuss
Copy link
Contributor

ehuss commented Jan 13, 2020

I was able to record exactly what happens. The timeline is:

T1. libcore.rmeta emitted
T2. backtrace build starts
T3. libcore.rlib emitted
T4. backtrace loads libcore.rlib
T5. backtrace writes dep-info with libcore.rmeta and libcore.rlib
T6. backtrace finishes
T7. Cargo reverses backtrace dep-info timestamp to T2 (here) (this is intended to deal with files that are modified in the middle of the build)

The result is that libcore.rlib's timestamp is T3 and backtrace dep-info timestamp is T2, and since T3 > T2, the next time Cargo runs it thinks backtrace needs to be rebuilt.

I'm not sure how to fix this. One solution would be to change the rustc priority to load rmeta over rlib, and have -Zbinary-dep-depinfo only emit one file. Or Cargo could hash the files 😉. Maybe @alexcrichton has ideas?

@alexcrichton
Copy link
Member

I like the idea of inverting rustc's preference, using only the rmeta rather than both the rmeta and rlib if they're available. Other than that though I don't know of a great way to solve this :(

I may be missing something though, is this rustc-specific? This seems like a bug that everyone should be hitting naively which makes it quite serious?

@ehuss
Copy link
Contributor

ehuss commented Jan 13, 2020

I may be missing something though, is this rustc-specific? This seems like a bug that everyone should be hitting naively which makes it quite serious?

It is only with -Zbinary-dep-depinfo. Also, the timing has to be just right for the rlib to be created in a very small window (the time between T2 and T4 is extremely small).

@alexcrichton
Copy link
Member

Ah I see, makes sense!

Here's another possible question and/or solution. When Cargo builds libbacktrace it's presumably only passing --extern=libcore.rmeta, so I think it's rustc's automatic logic to pick up *.rlib. Is that correct? If so it may be more correct to, if --extern is passed, disable all other auto-loading?

@ehuss
Copy link
Contributor

ehuss commented Jan 13, 2020

When Cargo builds libbacktrace it's presumably only passing --extern=libcore.rmeta, so I think it's rustc's automatic logic to pick up *.rlib. Is that correct? If so it may be more correct to, if --extern is passed, disable all other auto-loading?

Backtrace only sees rustc-std-workspace-core via --extern. core is loaded as a dependency of that. (Via CrateLoader::resolve_crate_deps I think?)

@Mark-Simulacrum
Copy link
Member

I like the idea of inverting rustc's preference, using only the rmeta rather than both the rmeta and rlib if they're available. Other than that though I don't know of a great way to solve this :(

I think this is our best bet -- furthermore, I wonder if there's some wins to be had in terms of compile times. It seems like we are currently loading libcore's rmeta/rlib for all crates out there, which presumably is not great (more IO, etc.).

I can pursue a PR to that effect soon.

@alexcrichton
Copy link
Member

@ehuss aha ok that makes sense as well.

Then yeah I think your suggestion is indeed the only thing I can think of as well!

@Mark-Simulacrum
Copy link
Member

Hm, actually, in going to do this, it sounds like we can't quite just emit one of them, per @petrochenkov's comment "Even if rmeta is used for reading metadata, rlib can still be used for reading object code, in that case both should indeed be in dependencies?" -- right?

@alexcrichton
Copy link
Member

When building an rlib we never use contents of upstream rlibs. When building dynamically linked artifacts, though (or executables) we do use upstream object code. (this is basically pipelining)

@Mark-Simulacrum
Copy link
Member

Aha, okay, so it sounds like a partial fix would be to:

  • If we're producing rmeta/rlib:
    • emit just rmeta dependency
  • if we're producing dylib/cydlib/binary:
    • emit just rlib dependency

Does that sound right? Basically, we emit "worst case" for either situation which I think might mean that for dylibs this bug persists -- since they'll start compilation before the rlib is finished -- but I don't know how much we can do about it under the current model.

@alexcrichton
Copy link
Member

That should be right yeah, and I think the dylib bug won't be an issue because Cargo won't start libstd until all subsequent rlib compilations are finished (e.g. it doesn't pipeline it)

@Mark-Simulacrum
Copy link
Member

Great! Okay, then I'll try to get that impl up.

(I presume the "dylib bug won't be an issue" also applies to dylibs in the wild, right?)

@alexcrichton
Copy link
Member

That's the theory at least!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-bug Category: This is a bug. T-bootstrap Relevant to the bootstrap subteam: Rust's build system (x.py and src/bootstrap)
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants