1568168 - `mach build binaries` spends a lot of time building cargo/rust stuff(?) when nothing has changed

Status: RESOLVED WORKSFORME

(Firefox Build System :: General, defect)

Description

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

STR:

1. ./mach build
2. ./mach build binaries

Expected:
Step 2 should be very quick.

Actual:
Step 2 seems to spend many seconds (~14s on a 14c i9, 64GB, SSD, win10-64) building rust things that shouldn't have changed.
There are a few suspicious "force-cargo-..." lines at the beginning -- are we forcing things even when not always needed?

Full log below.

Touching one test file only adds a fraction of a second.
Touching one cpp file (used in xul.dll) adds ~17s. So half the time is still spent in those things I haven't modified.

0:02.24 c:\mozilla-build\bin\mozmake.EXE -j28 -s binaries
0:04.60 Elapsed: 1.94s; From dist/include: Kept 0 existing; Added/updated 5891; Removed 0 files and 0 directories.
0:04.71 js/src/rust/force-cargo-library-build
0:04.71 js/src/frontend/binast/force-cargo-host-program-build
0:04.71 toolkit/library/rust/force-cargo-library-build
0:04.73 testing/geckodriver/force-cargo-program-build
0:04.90 Blocking waiting for file lock on package cache lock
0:04.91 Blocking waiting for file lock on package cache lock
0:04.91 Blocking waiting for file lock on package cache lock
0:05.76 Blocking waiting for file lock on package cache lock
0:06.52 Blocking waiting for file lock on package cache lock
0:07.25 Blocking waiting for file lock on package cache lock
0:07.95 Blocking waiting for file lock on package cache lock
0:07.97 Blocking waiting for file lock on package cache lock
0:07.99 Blocking waiting for file lock on package cache lock
0:07.99 Blocking waiting for file lock on package cache lock
0:07.99 Blocking waiting for file lock on package cache lock
0:07.99 Blocking waiting for file lock on build directory
0:07.99 Blocking waiting for file lock on package cache lock
0:08.00 Blocking waiting for file lock on package cache lock
0:08.02 Finished dev [optimized + debuginfo] target(s) in 3.25s
0:08.04 Finished dev [optimized + debuginfo] target(s) in 3.27s
0:08.26 Finished dev [optimized + debuginfo] target(s) in 3.49s
0:08.40 Compiling lazy_static v1.2.0
0:08.41 Compiling cfg-if v0.1.6
0:08.42 Compiling bitflags v1.0.4
0:08.43 Compiling quick-error v1.2.1
0:08.46 Compiling utf8-ranges v1.0.0
0:08.48 Compiling unicode-width v0.1.4
0:08.50 Compiling strsim v0.7.0
0:08.50 Compiling libc v0.2.51
0:08.50 Compiling memchr v2.2.0
0:08.66 Compiling net2 v0.2.33
0:08.67 Compiling log v0.4.6
0:08.67 Compiling uuid v0.6.5
0:08.71 Compiling crossbeam-utils v0.6.5
0:08.71 Compiling thread_local v0.3.6
0:08.76 Compiling textwrap v0.9.0
0:08.77 Compiling humantime v1.1.1
0:08.87 Compiling num_cpus v1.7.0
0:08.87 Compiling miniz_oxide v0.1.2
0:08.87 Compiling time v0.1.40
0:08.88 Compiling bzip2-sys v0.1.6
0:08.88 Compiling aho-corasick v0.6.8
0:09.06 Compiling tokio-io v0.1.7
0:09.06 Compiling want v0.0.6
0:09.06 Compiling tungstenite v0.8.1
0:09.11 Compiling miow v0.2.1
0:09.18 Compiling clap v2.31.2
0:09.21 Compiling plist v0.4.0
0:09.22 Compiling futures-cpupool v0.1.8
0:09.22 Compiling crossbeam-epoch v0.7.1
0:09.22 Compiling tokio-executor v0.1.7
0:09.22 Compiling crossbeam-channel v0.3.7
0:09.27 Compiling bzip2 v0.3.2
0:09.34 Compiling regex v1.0.3
0:09.40 Compiling miniz_oxide_c_api v0.1.2
0:09.40 Compiling headers v0.2.1
0:09.40 Compiling msdos_time v0.1.6
0:09.40 Compiling cookie v0.11.0
0:09.40 Compiling chrono v0.4.6
0:09.62 Compiling tokio-codec v0.1.0
0:09.62 Compiling h2 v0.1.12
0:09.71 Compiling mozrunner v0.9.0 (C:\mozilla-source\mozilla-central\testing\mozbase\rust\mozrunner)
0:09.71 Compiling tokio-current-thread v0.1.6
0:09.71 Compiling tokio-timer v0.2.11
0:09.75 Compiling flate2 v1.0.1
0:09.77 Compiling crossbeam-deque v0.6.3
0:10.01 Compiling mio v0.6.16
0:10.02 Compiling mozversion v0.2.0 (C:\mozilla-source\mozilla-central\testing\mozbase\rust\mozversion)
0:10.08 Compiling tokio-threadpool v0.1.10
0:10.14 Compiling zip v0.4.2
0:10.45 Compiling tokio-fs v0.1.3
0:10.77 Compiling tokio-reactor v0.1.3
0:11.14 Compiling tokio-udp v0.1.1
0:11.14 Compiling tokio-tcp v0.1.1
0:11.43 Compiling tokio v0.1.11
0:11.84 Compiling hyper v0.12.19
0:12.53 Compiling warp v0.1.16
0:13.16 Compiling webdriver v0.39.0 (C:\mozilla-source\mozilla-central\testing\webdriver)
0:14.48 Compiling geckodriver v0.24.0 (C:\mozilla-source\mozilla-central\testing\geckodriver)
0:17.88 Finished dev [optimized + debuginfo] target(s) in 13.10s
0:18.16 317 compiler warnings present.
0:18.25 Overall system resources - Wall time: 16s; CPU: 29%; Read bytes: 1835008; Write bytes: 221351936; Read time: 1; Write time: 0
To view resource usage of the build, run |mach resource-usage|.
0:18.28 Your build was successful!

Comment 1

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

I thought I'd be clever and try a clobber (and even delete the obj directory), and rebuild... Now ./mach build binaries takes 2m40s. Then 3m28s. 😱

Destroyed sccache, rebuilt, now down to 10s, I can live with that.

So this bug here may just be something wrong with my configuration.
Is "Blocking waiting for file lock on package cache lock" a clue?

So feel free to close the bug, but any advice would be welcome, thanks.

Comment 2

[Jan Varga [:janv]]

I experienced a similar problem. I removed .cargo .mozbuild .rustup and then ran mach bootstrap
I also switched to .mozbuild/sccache/sccache (used .cargo/bin/sccache before).
It seems "mach build" is fast again now.

Comment 3

[Jan Varga [:janv]]

Btw, I still see several "Blocking waiting for file lock on package cache lock", but my build is much faster now.

Comment 4

[Jean-Yves Avenard [:jya]]

I'm experiencing the issue too :)

Comment 5

[Mike Hommey [:glandium]]

you too wrt which comment?

Comment 6

[Jean-Yves Avenard [:jya]]

(In reply to Jan Varga [:janv] from comment #2)

I experienced a similar problem. I removed .cargo .mozbuild .rustup and then ran mach bootstrap
I also switched to .mozbuild/sccache/sccache (used .cargo/bin/sccache before).
It seems "mach build" is fast again now.

FWIW, I did just that. made no difference.

over 1m wasted recompiling every single time :(

Comment 7

[(Away)]

If I understand correctly, force-cargo-...-build is the only way the build system can be sure it has up to date Rust objects, because it can't know through any better means.

If this is the case, I'd love to have some way to tell my build, "I promise I didn't change any Rust, please assume it's all up to date, the blame is completely on me if I'm wrong about this."

Comment 8

[Simon Sapin (:SimonSapin)]

This is at least two different bugs.

0:06.52 Blocking waiting for file lock on package cache lock

This line being printed N times is a sign that at least N+1 copies of Cargo running concurrently. It would be nice to run Cargo only once and tell it up-front everything it needs to do (with -p foo multiple times, or --all, or default-members ) rather that having multiples copies competing for a shared resource.

0:08.40 Compiling lazy_static v1.2.0

Such lines should not be printed when no source file or configuration has changed since the same cargo build command was run. Spurious recompilations like this are bugs that should be fixed, not (just) papered over with a “I promise I didn’t touch Rust code” flag. (Which would be incorrect for example when touching a C++ header that is read by bindgen to generate Rust bindings.)

If you manage to find steps to reproduce, building with a CARGO_LOG=cargo::core::compiler::fingerprint environment variable should print some details about why Cargo things some crate (and therefore those that transitively depend on it) needs to be rebuilt.

https://github.com/servo/mozjs/pull/203 is an example of a fix for such a bug: a combination of a build.rs script being over-eager in using
rerun-if-changed and calling something that ends up writing to the source directory.

Comment 9

[Mike Hommey [:glandium]]

(In reply to Simon Sapin (:SimonSapin) from comment #8)

0:06.52 Blocking waiting for file lock on package cache lock

This line being printed N times is a sign that at least N+1 copies of Cargo running concurrently. It would be nice to run Cargo only once and tell it up-front everything it needs to do (with -p foo multiple times, or --all, or default-members ) rather that having multiples copies competing for a shared resource.

That's not possible because of e.g. features merging.

Comment 10

[Simon Sapin (:SimonSapin)]

Are there really 13 different sets of features wanted? In what cases is merging undesirable?

Reducing the number of Cargo instances running concurrently may be worthwhile even if it doesn’t go all the way to one.

Comment 11

[Mike Hommey [:glandium]]

There aren't 13 different cargo invocations. Check out rust_targets in $objdir/root.mk. Each item in that variable is going to cause an invocation. On my machine there are 4. What did change recently though (around 1.36 or 1.37 iirc), is that a single cargo now can print out the lock message multiple times for some reason.

Comment 12

[(Away)]

(In reply to Simon Sapin (:SimonSapin) from comment #8)

Spurious recompilations like this are bugs that should be fixed, not (just) papered over with a “I promise I didn’t touch Rust code” flag. (Which would be incorrect for example when touching a C++ header that is read by bindgen to generate Rust bindings.)

To be clear, I find the scanning time from force-cargo-X to be unacceptably high even when there are no recompilations. Whenever my rebuild time exceeds the threshold where I don't want to stare at my terminal and instead switch windows to e.g. my bugmail, at that point the loss of focus has already pushed my productivity over a cliff.

Comment 13

[Nathan Froyd [:froydnj]]

(In reply to Mike Hommey [:glandium] (high latency) from comment #9)

(In reply to Simon Sapin (:SimonSapin) from comment #8)

0:06.52 Blocking waiting for file lock on package cache lock

This line being printed N times is a sign that at least N+1 copies of Cargo running concurrently. It would be nice to run Cargo only once and tell it up-front everything it needs to do (with -p foo multiple times, or --all, or default-members ) rather that having multiples copies competing for a shared resource.

That's not possible because of e.g. features merging.

It's also not possible because all of those invocations are not building for the same build settings (target and panic= at a minimum).

Comment 14

[Florian Quèze [:florian]]

(In reply to Gerald Squelart (he/him) (not at Mozilla since 2022-09-15) from comment #0)

STR:

1. ./mach build
2. ./mach build binaries

Here's a profile of this done today: https://share.firefox.dev/4aZUOnY
No actual compilation is happening, most of the time is the overhead of recursive make.