Extremely slow build times in Rust?

[tyleryep]

My Rust build is taking around 20 seconds to build on my new Macbook Pro, sometimes even freezing my computer in the process. I have compared the runtime to an equivalent computer, and there it builds and runs almost instantly.

Using the profiler in Mac Instruments, the execution of my build seems to be doing nothing for most of the 20 seconds, and then only rendering the output at the very end.

I have uninstalled and reinstalled rust and cargo several times with different versions, as well as running cargo clean, with no luck. This occurs for all projects and builds that I have tried.

Any ideas?

I am using macOS Mojave 10.14.6. Have already compared the disk write speeds to another computer and did not see any problems.

rustc 1.39.0 (4560ea788 2019-11-04)

[sanxiyn]

I have compared the runtime to an equivalent computer, and there it builds and runs almost instantly.

More information about this computer would help diagnosis.

A hunch is that this is often a problem with linker. macOS linker historically has been especially problematic.

[tyleryep]

The other computer(s) were also Macbook Pros, 2017. I believe they are all running the same OS.

Is there anything I can do to identify a problem with the linker or a case of this happening somewhere else?

[kornel]

Try compiling with -Z time-passes.

[anon80458984]

To make sure I understand the problem correctly, you have a situation where:

crate000 + machine X = slow
crate000 + machine Y = fast

any cargo package + machine X = slow

?

[tyleryep]

@sanxiyn You are likely right, it might be a problem with the linker. When I run rustc with -Z time-passes I get the following output: (after the "linking" line at the end it stalls for ~20 seconds)

@anon80458984 Yes, that situation is correct.

Any ideas about what I should try next? Still not quite sure where to go from here...

(base) DN51vsrt:rust [master]$ rustc -Z time-passes --edition=2018 --crate-name assign6 /Users/.../program/rust/src/lib.rs --color always --crate-type lib --emit=dep-info,metadata,link -C debuginfo=2 -C metadata=d1eb96dd185ac012 -C extra-filename=-d1eb96dd185ac012 --out-dir /Users/.../program/rust/target/debug/deps -C incremental=/Users/.../program/rust/target/debug/incremental -L dependency=/Users.../program/rust/target/debug/deps --extern lazy_static=/Users/.../program/rust/target/debug/deps/liblazy_static-29b10d75700e38d7.rmeta
*       time: 0.008	parsing
*       time: 0.000	attributes injection
*       time: 0.001	garbage-collect incremental cache directory
*       time: 0.000	recursion limit
*       time: 0.000	plugin loading
*       time: 0.000	plugin registration
*       time: 0.002	pre-AST-expansion lint checks
*       time: 0.005	background load prev dep-graph
*       time: 0.001	crate injection
*         time: 0.103	expand crate
*         time: 0.000	check unused macros
*       time: 0.104	expansion
*       time: 0.000	maybe building test harness
*       time: 0.002	AST validation
*       time: 0.000	maybe creating a macro crate
*       time: 0.013	name resolution
*       time: 0.000	complete gated feature checking
*       time: 0.000	blocked while dep-graph loading finishes
*       time: 0.014	lowering AST -> HIR
*       time: 0.002	early lint checks
*         time: 0.000	validate HIR map
*       time: 0.006	indexing HIR
*       time: 0.003	load query result cache
*       time: 0.000	dep graph tcx init
*         time: 0.001	looking for entry point
*         time: 0.000	looking for plugin registrar
*         time: 0.001	looking for derive registrar
*       time: 0.003	misc checking 1
*       time: 0.002	type collecting
*       time: 0.001	impl wf inference
*         time: 0.007	unsafety checking
*         time: 0.001	orphan checking
*       time: 0.010	coherence checking
*       time: 0.001	wf checking
*       time: 0.001	item-types checking
*       time: 0.009	item-bodies checking
*         time: 0.000	match checking
*         time: 0.000	liveness checking + intrinsic checking
*       time: 0.000	misc checking 2
*       time: 0.000	MIR borrow checking
*       time: 0.000	dumping Chalk-like clauses
*       time: 0.004	MIR effect checking
*       time: 0.000	layout testing
*         time: 0.006	privacy access levels
*         time: 0.001	private in public
*         time: 0.005	death checking
*         time: 0.000	unused lib feature checking
*           time: 0.081	crate lints
*           time: 0.000	module lints
*         time: 0.081	lint checking
*         time: 0.001	privacy checking modules
*       time: 0.094	misc checking 3
*           time: 0.003	collecting roots
*           time: 0.000	collecting mono items
*         time: 0.004	monomorphization collection
*         time: 0.003	codegen unit partitioning
*       time: 0.027	metadata encoding and writing
*         time: 0.000	codegen to LLVM IR
*         time: 0.000	assert dep graph
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::type_of
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::generics_of
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::predicates_of
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::mir_const_qualif
*       time: 0.005	LLVM passes
*                 time: 0.001	encode_query_results for rustc::ty::query::queries::optimized_mir
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::promoted_mir
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::unsafety_check_result
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::typeck_tables_of
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::used_trait_imports
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::mir_borrowck
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::const_eval
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::check_match
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::symbol_name
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::codegen_fn_attrs
*                 time: 0.000	encode_query_results for rustc::ty::query::queries::codegen_fulfill_obligation
*                 time: 0.001	encode_query_results for rustc::ty::query::queries::specialization_graph_of
*               time: 0.002	encode query results
*             time: 0.007	serialize query result cache
*           time: 0.007	persist query result cache
*               time: 0.001	getting serialized graph
*               time: 0.002	encoding serialized graph
*             time: 0.003	encode dep-graph
*           time: 0.003	persist dep-graph
*         time: 0.011	serialize dep graph
*       time: 0.020	codegen
*       time: 0.000	serialize work products
*       time: 0.006	linking
*       time: 24.596		total

[sanxiyn]

The natural next step is to confirm whether two machines have different linkers, and if so, update the slow machine such that it has the same linker as the fast machine.

[anon80458984]

I admit up front I don't know how to solve this problem and am suggesting in the dark.

So looking at the log time log above, you have ~ 50ish lines, where each line is .00N, .01N, or .02N - adding up to ~ 1 second -- then the linker hangs and makes you wait for ~23 seconds. This further supports @sanxiyn 's intuition that the linker is the problem.

Is it possible to use something like strace or dtrace to trace the system calls? (I'm pretty sure this is possible, I just don't know how to do it on OSX). The goal is to get the terminal to dump all kernel calls. It'll be a bunch of noise at first, but should provide insights during the 20 second wait, to see what precisely it is blocking on.

[stevensonmt]

Disclaimer: I claim no specific knowledge of this problem or how to troubleshoot it.

A quick google of linker problems with MacOS sent me to various mentions of the LLVM LLD linker as a drop-in replacement for the GNU system defaults. It is supposed to be much faster. Is there a way to check if one of your machines has LLD installed and the other does not?

[uberjay]

I wouldn't recommend going with lld in macOS. I've tried several times in the past, and it never ends well. I gave it another try using a freshly-build llvm master and it did not work. There are various issues. Sometimes binaries link, sometimes they do not. If they do link, they (for me) always segfault on execution.

If you would like to try it, you can point rustc at your (perhaps freshly built) copy of ld64.lld like so:

export RUSTFLAGS="-C linker=/...llvm-build.../bin/ld64.lld -C linker-flavor=ld64.lld"
cargo build -v

Attempting to link C code with clang+lld fails to find libSystem.dylib; the Mach-O support in lld is apparently woefully bitrotted.

Furthermore, allegedly ld64 is not nearly as sluggish as other platform linkers, so the performance boost wouldn't be as great. Which makes me think there may be something else going on with your system that's causing link times to be so high. Disk I/O issues?

If it were me, I'd try running the linker command with dtruss to track down where it's spending its time: DTrace: [even better than] strace for OS X | 8th Light

[tyleryep]

I ran dtruss -d -e cargo test and saw this huge set of outputs, with around 100 more of them after. Any ideas where these are coming from?

Looks like psynch_cvwait is taking up most of the time. I can rerun with more args if that helps.

RELATIVE ELAPSD SYSCALL(args) = return

86374 504976 psynch_cvwait(0x7FAB8C403090, 0x2B0100002C00, 0x0)		= -1 Err#316
86400 7 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86403 1 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86410 2 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0
86419 500910 psynch_cvwait(0x7FAB8C403090, 0x2C0100002D00, 0x0)		= -1 Err#316
86442 6 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86445 1 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86450 1 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0
86459 500194 psynch_cvwait(0x7FAB8C403090, 0x2D0100002E00, 0x0)		= -1 Err#316
86484 7 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86496 4 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86505 2 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0
86518 500958 psynch_cvwait(0x7FAB8C403090, 0x2E0100002F00, 0x0)		= -1 Err#316
86543 7 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86547 1 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86554 2 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0
86564 500657 psynch_cvwait(0x7FAB8C403090, 0x2F0100003000, 0x0)		= -1 Err#316
86594 7 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86597 2 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86603 1 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0
86611 505006 psynch_cvwait(0x7FAB8C403090, 0x300100003100, 0x0)		= -1 Err#316
86638 8 ioctl(0x2, 0x40087468, 0x7FFEE19BB4D8)		= 0 0
86642 1 ioctl(0x2, 0x40087468, 0x7FFEE19BB3C8)		= 0 0
86649 2 gettimeofday(0x7FFEE19BAF60, 0x0, 0x0)		= 0 0

Other large syscall times:

2694 25778660 poll(0x70000AEB2F40, 0x2, 0xFFFFFFFFFFFFFFFF)		 = 2 0

2904 12022102 open("/Users/tyleryep/Documents/.../target/debug/deps/lib-c052021c9e23d927.d\0", 0x1000000, 0x1B6)		 = 6 0

3886 1682999 open("/Users/tyleryep/Documents/.../target/debug/deps/lib-c052021c9e23d927\0", 0x1000000, 0x1B6)		 = 6 0

[tyleryep]

I upgraded to macOS Catalina and that fixed everything. Very unexpected.

Thanks for all of the help friends!