Closed
Description
Updated to the latest nightly earlier today, and immediately started noticing a marked compile time slowdown in cargo build
(debug mode) for small projects.
EDIT: Turns out the slowdown is because it's dumping a core to /cores
, I worked this out when my machine became completely full 😁 .
Platform: macOS High Sierra.
NOTE (added by @pnkfelix): it appears you need to turn up a core dump threshold to observe this, e.g. via ulimit -c unlimited
$ rustup update ~/tmp
info: syncing channel updates for 'stable-x86_64-apple-darwin'
info: syncing channel updates for 'nightly-x86_64-apple-darwin'
info: checking for self-updates
stable-x86_64-apple-darwin unchanged - rustc 1.22.1 (05e2e1c41 2017-11-22)
nightly-x86_64-apple-darwin unchanged - rustc 1.24.0-nightly (1956d5535 2017-12-03)
$ cargo new --bin hello_nightly && cd hello_nightly ~/tmp
Created binary (application) `hello_nightly` project
$ time rustup run nightly cargo build ~/tmp/hello_nightly (master*)
Compiling hello_nightly v0.1.0 (file:///Users/gib/tmp/hello_nightly)
Finished dev [unoptimized + debuginfo] target(s) in 3.0 secs
rustup run nightly cargo build 0.32s user 1.17s system 46% cpu 3.229 total
$ touch src/main.rs && time rustup run nightly cargo build ~/tmp/hello_nightly 3s (master*)
Compiling hello_nightly v0.1.0 (file:///Users/gib/tmp/hello_nightly)
Finished dev [unoptimized + debuginfo] target(s) in 2.90 secs
rustup run nightly cargo build 0.33s user 1.07s system 44% cpu 3.133 total
$ cd .. ~/tmp/hello_nightly 3s (master*)
$ cargo new --bin hello_stable && cd hello_stable ~/tmp
Created binary (application) `hello_stable` project
$ time rustup run stable cargo build ~/tmp/hello_stable (master*)
Compiling hello_stable v0.1.0 (file:///Users/gib/tmp/hello_stable)
Finished dev [unoptimized + debuginfo] target(s) in 0.53 secs
rustup run stable cargo build 0.37s user 0.23s system 65% cpu 0.908 total
$ touch src/main.rs && time rustup run stable cargo build ~/tmp/hello_stable 1s (master*)
Compiling hello_stable v0.1.0 (file:///Users/gib/tmp/hello_stable)
Finished dev [unoptimized + debuginfo] target(s) in 0.31 secs
rustup run stable cargo build 0.33s user 0.17s system 92% cpu 0.542 total
Sorry if this is a duplicate, didn't see anything relevant in the issue tracker.
Metadata
Metadata
Assignees
Labels
Type
Projects
Milestone
Relationships
Development
No branches or pull requests
Activity
gibfahn commentedon Dec 4, 2017
Doesn't seem to happen with
cargo build --release
:nikomatsakis commentedon Dec 7, 2017
@gibfahn I'm a bit confused. If I'm not misreading things, it appears that the nightly build is faster (at least in the one case where the numbers are not identical):
vs
nikomatsakis commentedon Dec 7, 2017
No, nm, I was getting confused by time output. I see... 3.229 total vs 0.908 total. =)
gibfahn commentedon Dec 7, 2017
Still happens with the newest nightly (
rustc 1.24.0-nightly (5a2465e2b 2017-12-06)
). Reproduced on someone else's laptop as well (also macOS).Pretty easy to reproduce:
EDIT: Can't reproduce this on Ubuntu
nikomatsakis commentedon Dec 7, 2017
@gibfahn just to be clear, if you diff those two projects, do you see any difference? i.e., it seems to me you should be able to just have one project and do
cargo +nightly build
and compare tocargo +stable build
... can you check that?nikomatsakis commentedon Dec 7, 2017
I don't see any significant difference on linux, anyway.
gibfahn commentedon Dec 7, 2017
@nikomatsakis are you running on macOS? I'll keep a list of platforms I tried it on.
Using the shortened script above I reproduced with the same code.
Mark-Simulacrum commentedon Dec 9, 2017
I cannot reproduce on macOS High Sierra 10.13.2.
gibfahn commentedon Dec 11, 2017
Odd, not sure what the difference could be.
In case it's a hardware thing, this is my machine's configuration:
Mark-Simulacrum commentedon Dec 12, 2017
It might be helpful to have a bash script that'll run the commands for me just in case, but as far as I can tell I have the same make of hardware, just a slightly different version of macOS. Seems unlikely that would be the culprit, though...
gibfahn commentedon Dec 12, 2017
@Mark-Simulacrum the script in #46505 (comment) is exactly what I'm doing.
I tried this on a different machine (same OS level, different hardware configuration) and it didn't have the same problem. I'm not sure how else to debug.
Mark-Simulacrum commentedon Dec 12, 2017
Clearing out
~/.cargo
or at least make sure both machines have the same content might help.gibfahn commentedon Dec 13, 2017
Did an uninstall and reinstall (
rustup self uninstall
), and I can no longer reproduce:I did have a fair amount of stuff in
$CARGO_HOME
, so I guess something in there must have affected it:Thanks for troubleshooting!
3 remaining items
[-]`cargo build` slowdown on latest nightly with Hello World project[/-][+]`cargo build` dumps core on latest nightly with Hello World project (macOS)[/+]arielb1 commentedon Dec 21, 2017
Assigning to @pnkfelix
Could you try to confirm you can reproduce this today?
pnkfelix commentedon Dec 21, 2017
I have now reproduced this, by invoking
ulimit -c unlimited
before doing the build, as described in @gibfahn 's commentpnkfelix commentedon Dec 21, 2017
This apparently was injected between the nightlies for 2017-11-25 and 2017-11-26:
rustup
's build ofcargo
didn't change between those dates, but of courserustc
did:pnkfelix commentedon Dec 21, 2017
The last entries in ouput from
RUST_LOG=debug
before the core dump are:Additionally, I tried running
rustc
underlldb
to see if the stacktrace there would be more informative, but it did not tell me much:pnkfelix commentedon Dec 21, 2017
I suppose another option is to load the core dump itself into the debugger and see what it says:
I have to go home now. I probably will not look at this again until tomorrow (and it will have to take lower precedence than fixes to the beta branch in preparation for the upcoming release).
pnkfelix commentedon Dec 21, 2017
In other fronts of investigation: I worked on analyzing the actual
rustc
invocation thatcargo
is using for this code, since I do not see this same behavior of dumping core in my day-to-day work on Rust.Starting from the original invocation and whittling it down, I have determined that adding
-C debuginfo=2
to therustc
invocation is how one replicates the core dump (and to be clear: this is on OS X, withulimit -c unlimited
)So:
pnkfelix commentedon Dec 21, 2017
Oh.
Looking at my "OS X" terminal window during that long pause where the core dump is happening, the title bar of the window shows (I think) the current active child process.
In this case, it appears to be
dsymutil
dsymutil`main + 8421
atframe #26
Maybe something has gone wrong with how we are invoking that utility?
kennytm commentedon Dec 21, 2017
dsymutil? Sounds like #46346 (fixed 8 hours ago). Check with the next nightly?
DICompileUnit
bugs in LLVM #46772gibfahn commentedon Dec 28, 2017
I can no longer reproduce this with the latest nightly, so I'm guessing #46346 was the fix.
Thanks for all the investigation!