improve rustc wrapper startup time?

[matthiaskrgr]

time ~/.rustup/toolchains/master/bin/rustc >& /dev/null
0,040 total

time ~/.cargo/bin/rustc >& /dev/null
0,272 total

That's almost 7x slower.
I wonder if there is some something we can do to get these numbers a bit closer?

[jyn514]

@matthiaskrgr this is about the rustup wrapper, not the x.py rustc shim, right? If so I think this should be moved to https://github.com/rust-lang/rustup/.

[matthiaskrgr]

Ah, ~/.cargo/bin/rustc is rustup? Yes, the issue should be moved then. :)

[kinnison]

I can confirm that the difference in performance is around 6x:

listless% hyperfine ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc rustc 
Benchmark #1: /home/dsilvers/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc
  Time (mean ± σ):      11.3 ms ±   0.9 ms    [User: 6.9 ms, System: 4.3 ms]
  Range (min … max):    10.1 ms …  15.4 ms    252 runs
 
Benchmark #2: rustc
  Time (mean ± σ):      71.2 ms ±   2.3 ms    [User: 60.0 ms, System: 11.2 ms]
  Range (min … max):    67.3 ms …  76.2 ms    41 runs
 
Summary
  '/home/dsilvers/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc' ran
    6.31 ± 0.54 times faster than 'rustc'
listless%                                                                                

[kinnison]

Looking locally, ca. 15ms are before main() is entered (presumably due to dynamic link time for all the libraries rustup uses by dint of being linked to curl).

It looks like about 25ms is taken parsing manifest files, sadly this is also done twice, and thus accounts for the vast majority of the extra time. The toml parser must be quite inefficient.

It might be possible to knock one of those parse steps on the head since in theory we only need to parse once, but it'll involve quite a bit of refactoring.

If someone wants to begin to look at this, then the place to start is the config.rs file, around line 620 which is find_or_install_override_toolchain_or_default(). In the sub-function components_exist() you can see it acquire the manifest (since it needs it) and then it lists the components in order to check that everything needed is installed. The list_components() function though ends up loading the manifest itself. Perhaps the distributable toolchain could cache the manifest having loaded it?

[rbtcollins]

To help triage this, how much does this contribute to typical build times? like, - sure we can put a chunk of time into making this snappy, and that would be good, but if a typical build is 1500ms ... ?

[jyn514]

@rbtcollins I wouldn't notice so much on builds, but this hurts things like rustc --explain E0111 or rustc --help.

$ time /home/joshua/.local/lib/rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc --help >/dev/null
real	0m0.050s
user	0m0.026s
sys	0m0.020s
$ time rustc --help >/dev/null
real	0m0.157s
user	0m0.129s
sys	0m0.028s
$ time pip --help >/dev/null
real	0m0.206s
user	0m0.178s
sys	0m0.028s
$ time go help >/dev/null
real	0m0.022s
user	0m0.008s
sys	0m0.017s

[matthiaskrgr]

to addd to the list:

time clang >&/dev/null 
clang >&/dev/null  0,04s user 0,03s system 96% cpu 0,064 total

time gcc >& /dev/null
gcc >&/dev/null  0,00s user 0,01s system 86% cpu 0,009 total

[kinnison]

@matthiaskrgr

Comparing with C compilers is disingenuous since the number of rustc invocations for a similarly sized codebase will be many fewer. For example, rustup is around 130 .rs files, but including its dependencies the total rustc invocations is only 320 or so. If we assume a wasted 35ms (the repeated manifest parse) of CPU time on my computer per rustc invocation and we generously assume that all that waste is reflected in the wallclock compile time at the same parallelism that the build occurs at, then of the 83s it took my computer to build rustup just now at 6.1x parallel, then that's 11375ms wasted which at 6.1x parallel is 1.864s of wallclock time or 2.2% of all build time in a debug build.

The same maths on a release build, 11375ms wasted for a total build time of 195s is only 0.95% of the total runtime of the build.

@jyn514

Considering the rustc --explain or rustc --help scenarios is also disingenuous. Most humans don't need to run those repeatedly in tight loops, and will take far longer than the wasted 50ms or so even noticing the screen updated let alone reading and grokking the output.

however

Having said all that, I do think it's worth correcting the double-load of the manifest since it's wasteful to do that anyway, and that shouldn't be too complex to do in a grungy way; or only medium hard to do nicely.

What would be of even more use though is working out how it takes 35ms on a 4GHz CPU core to parse the manifest, that's utterly abysmal.

[kinnison]

Further investigation yields:

The majority of the time spent parsing the manifest is in the toml load itself, i.e. before we apply any semantic understanding to the manifest. The channel is around 700k and will only get larger over time. Another possible improvement to do would be to trim out anything not relevant to the toolchain being installed when fetching the manifest. That ought not to be too complex to do and would speed up future operations since the manifest would be significantly smaller

[kinnison]

I wrote a simple trimmer for the manifests to reduce the toml quantity in installed toolchains. Doing that results in the following (stable is untrimmed, beta is trimmed):

listless% echo stable > rust-toolchain                                        
listless% hyperfine rustc                                                     
Benchmark #1: rustc
  Time (mean ± σ):      69.8 ms ±   1.9 ms    [User: 59.5 ms, System: 10.2 ms]
  Range (min … max):    67.4 ms …  76.1 ms    42 runs
 
listless% echo beta > rust-toolchain                                          
listless% hyperfine rustc                                                    
Benchmark #1: rustc
  Time (mean ± σ):      19.6 ms ±   0.7 ms    [User: 14.2 ms, System: 5.4 ms]
  Range (min … max):    18.7 ms …  22.9 ms    128 runs
 
listless%                                                                    

(for reference, directly invoking rustc (stable or beta) without rustup in the way is ca. 11ms.

[kinnison]

@matthiaskrgr Assuming #2627 goes CI-green, you might want to try the binary from there and see how it affects performance for you.

[jyn514]

Most humans don't need to run those repeatedly in tight loops, and will take far longer than the wasted 50ms or so even noticing the screen updated let alone reading and grokking the output.

Well, I somewhat disagree: https://danluu.com/keyboard-latency/#humans-can-t-notice-100ms-or-200ms-latency. But the numbers after your change are a lot better :)

[matthiaskrgr]

Well, I made a small ICE-finder that runs rustc on all the files inside the rustc repo.
Luckily, I chose the master toolchain (I use a direct path to the master rustc) instead of using generic rustc already

Using rustc it would take at least 1.5 hours to only start rustc that many times (20K files)
With the direct path (skipping rustup wrapping), that's only 13 minutes..

[rbtcollins]

Running it serially, individually? Not terribly surprising.

I'm totally fine with rustup being faster, but development of rust itself isn't our primary use case: shipping rust toolchains to our users is, and running rustc in such a non idiomatic fashion is very much a specialised, developer of rust, need.

To me that says, if someone wants to make this faster, great, but we're unlikely to steer folk to this as a priority issue, unlike eg the corruption issues, locking issues, etc.

[rbtcollins]

Most humans don't need to run those repeatedly in tight loops, and will take far longer than the wasted 50ms or so even noticing the screen updated let alone reading and grokking the output.

Well, I somewhat disagree: https://danluu.com/keyboard-latency/#humans-can-t-notice-100ms-or-200ms-latency. But the numbers after your change are a lot better :)

If folk are running error explains in their game update loops - the context of that blog post - we have a whole new set of requirements to feed into rustup design.

Fast is good, and it is a feature.

But language servers and dev environments can avoid making the user wait for the invocation of the compiler in various ways; and should simply because remote dev environments pay latency in many ways, so having latency hiding techniques in play is just good design.

[kinnison]

When I was playing with my dodgy PR above, I ran into the fact that rustc-dev appears to be present in all toolchains in all targets, like rust-std is. @Mark-Simulacrum is going to have a look at why this might be, since regardless of whether or not we end up merging this "optimisation" we could do with knowing why rustc-dev is like this.

[joshtriplett]

Manifest parsing aside, would it potentially make sense for the top-level rustup-enabled cargo invocation to determine the toolchain and then set the RUSTC environment variable (if not already set) to point directly to the appropriate binary? That would eliminate almost all of the repeated startup times and manifest parses, and let rustc run directly.

[joshtriplett]

I just tested this approach building tide, which builds a total of 209 crates. I compared time cargo build to time RUSTC=$HOME/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/bin/rustc cargo build. Passing RUSTC reliably shaved off at least 20 CPU seconds, for around 6 seconds of build time on my 4-way laptop; that's around an 8% speedup to the build.

I think that'd be a worthwhile optimization.

[kinnison]

Is setting RUSTC purely something that cargo would want, or is it indicative of a general thing we should consider of setting RUSTC CARGO RLS etc. depending on which tools are installed? I assume setting this means that cargo simply doesn't invoke rustup's proxy?

One concern with this, rather than simply improving the startup performance of rustup, is how this might interact with how rustup sets up fallbacks for incomplete linked toolchains (i.e. as used in cargo/rustc development flows). If we can be sure that the fallback approach won't be broken by this, or that we can somehow detect when we'd invoke fallback case and not set the variables in that context, then it ought to be plausible.

[joshtriplett]

Is setting RUSTC purely something that cargo would want, or is it indicative of a general thing we should consider of setting RUSTC CARGO RLS etc. depending on which tools are installed?

I think it'd be reasonable to always set RUSTC from the rustup proxy, as long as the toolchain has rustc and RUSTC isn't already set in the environment.

I assume setting this means that cargo simply doesn't invoke rustup's proxy?

Right. See https://doc.rust-lang.org/cargo/reference/environment-variables.html ; cargo will invoke RUSTC when it wants to run rustc.

One concern with this, rather than simply improving the startup performance of rustup, is how this might interact with how rustup sets up fallbacks for incomplete linked toolchains (i.e. as used in cargo/rustc development flows). If we can be sure that the fallback approach won't be broken by this, or that we can somehow detect when we'd invoke fallback case and not set the variables in that context, then it ought to be plausible.

I think we can handle that case by just not setting RUSTC if our toolchain doesn't have rustc. We could take our path to rustc, resolve all symlinks, and make sure the result exists as a file.

[alex]

Is it worth reconsidering rustup as a chimera binary, given just how much stuff gets linked that isn't relevant to rustc (on my machine, in order of comedy value: libkr5, libssh2, librtmp, libcurl, etc.)

Alternatively, if a chimera is still desirable, splitting most of rustup into a dynamic library that's only loaded after we've checked if we're a proxy binary.

[rbtcollins]

Yes, worth considering. I have a project (#2441) to make proxies safe on windows as well which is related; that said, how much warm startup-time impact does linking those libraries have today? Cold time is irrelevant, since a single process invocation is trivially amortised over a full build. There is some complexity consider in having a separate binary though such as distribution and updating. I certainly don't have time to engage with it at the moment, though if someone else wanted to take it on I do have a few ideas related to #2441 that would be worth considering.

[kinnison]

IME having profiled it a bit, the majority of the startup time of the proxies, by a LONG margin, is the parsing of the channel toml. Hence I played with #2627 though it's the wrong solution, it's an approach to consider.

[rbtcollins]

@kinnison it may be different on Windows

[joshtriplett]

@konstin Yes, please do file a ticket for that in rust-lang/rust. And please give the details about bypassing the wrapper and invoking rustc directly, so that anyone trying to reproduce it can easily do so without getting sidetracked by the wrapper.

[konstin]

rust-lang/rust issue: rust-lang/rust#121631

[bjorn3]

I did some profiling and tokio-rs/tracing#3174 and alexcrichton/curl-rust#601 combined seem to be responsible for about 30% of the runtime.

[djc]

@bjorn3 thanks, very interesting! For the curl initialization, have you looked at where/how that work is triggered? Especially in the default configuration where we're not using curl at all it seems surprising that curl is still doing initialization work.

[bjorn3]

The curl crate has a global constructor which runs curl's initialization function. This in turn initializes OpenSSL. https://github.com/alexcrichton/curl-rust/blob/63f7213d7fd002f42f0e3124fc1da42655c0585a/src/lib.rs#L123-L151

[davidbarsky]

For the tokio-rs/tracing#3174, it might be worth trying to use the Targets filter instead of EnvFilter. Targets shouldn't depend on regex at the cost of only allowing target and level-based filtering. This might be enough for rustup!

[Kobzol]

I profiled this again after the recent improvements, and a majority of the time spent in rustup now is spent in manifest parsing (Manifest::parse), which takes ~25ms (out of ~44ms of total rustc runtime). I discussed this with Ed Page and it seems unlikely to get big perf. gains there. The manifest is pretty big (~1 MiB), but we only parse a relatively small fraction of data out of it, which TOML apparently isn't well prepared for.

Since this manifest is most likely auto-generated, I wonder if we could use a different (binary, more efficient) format for (de)serializing it? Or maybe rustup could load it as TOML, but reserialize it to disk in a binary format? It seems a bit wasteful to keep it as TOML, since it's being reparsed on every rustup invocation, even though it doesn't actually change unless the toolchain itself is updated (?).

[Kobzol]

Just as an example, parsing the file as JSON takes ~2ms (the input size is 700 KiB, so not that much smaller), so it's 10x faster, and there are likely much more efficient formats than JSON (although I tried bincode and MessagePack and both struggled with the way the Manifest file is defined, it uses some advanced serde trickery). Even using JSON would be nice.

[djc]

Thanks for looking into this! Do you have flamegraphs or other more detailed data?

I would maybe look at postcard. What advanced serde trickery are you referring to?

[lqd]

since it's being reparsed on every rustup invocation

What do you mean by this? The rustup wrapper is by now supposed to only be called "once" per compilation session by cargo, so not for every invocation.

[Kobzol]

What do you mean by this? The rustup wrapper is by now supposed to only be called "once" per compilation session by cargo, so not for every invocation.

I simply meant for every invocation of the rustup wrapper :) (e.g. for #2626 (comment))

I would maybe look at postcard. What advanced serde trickery are you referring to?

#[serde(from = "TargetsMap", into = "TargetsMap")] on PackageTargets and skip_serializing on reverse_renames both cause deserialization failures for Bincode 1/2, MsgPack (rmp_serde) and Postcard.

Thanks for looking into this! Do you have flamegraphs or other more detailed data?

(Recorded with samply record rustc)

[ChrisDenton]

So to ask the obvious first, do we need to load any metadata while in proxy mode? It's just to validate the components are installed right? Which feels more like the job of rustup proper so the proxies can just assume everything works.

[rami3l]

So to ask the obvious first, do we need to load any metadata while in proxy mode? It's just to validate the components are installed right? Which feels more like the job of rustup proper so the proxies can just assume everything works.

@ChrisDenton Wait, IIRC ensure_active_toolchain() was exactly the call that we brought back in v1.28.1 (and later renamed in v1.28.2) to avoid the previous breakage (and the same call that made a whole bunch of query-only functions unnecessarily async), and in that very context, this call should be necessary...

rustup/src/config.rs

Lines 534 to 538 in ac249c8

	if !should_ensure {
	return self.active_toolchain();
	}
	match self.ensure_active_toolchain(true, false).await {

@Kobzol This makes me wonder, what will the graph look like if the new behavior is used instead (RUSTUP_AUTO_INSTALL=0)?

[ChrisDenton]

Wait, IIRC ensure_active_toolchain() was exactly the call that we brought back in v1.28.1 (and later renamed in v1.28.2) to avoid the previous breakage, and in the very context of that breakage, this call should be necessary...

Ah right, that's a pain. So yeah persuading people to disable auto-install is the best call. 😉

My next thought would be to encode the essential information in a super simple binary format that's fast to load into memory.

[bjorn3]

Can we encode just the list of installed components in a binary file and only validate this file when running in proxy mode? And then leave any consistency checks that need to parse the full manifest to directly running rustup or when the proxy detects that a component is missing.

[Kobzol]

So to ask the obvious first, do we need to load any metadata while in proxy mode? It's just to validate the components are installed right? Which feels more like the job of rustup proper so the proxies can just assume everything works.

@ChrisDenton Wait, IIRC ensure_active_toolchain() was exactly the call that we brought back in v1.28.1 (and later renamed in v1.28.2) to avoid the previous breakage (and the same call that made a whole bunch of query-only functions unnecessarily async), and in that very context, this call should be necessary...

rustup/src/config.rs

Lines 534 to 538 in ac249c8

if !should_ensure {
return self.active_toolchain();
}

match self.ensure_active_toolchain(true, false).await {
@Kobzol This makes me wonder, what will the graph look like if the new behavior is used instead (RUSTUP_AUTO_INSTALL=0)?

With that env flag, rustc takes ~22ms, instead of ~48ms, so the manifest loading seems to be removed in that case.

[rami3l]

@Kobzol Thanks! So setting RUSTUP_AUTO_INSTALL=0 gives a reasonable workaround then.

It is also worth mentioning that with auto installation enabled, rustc --version can take up to minutes to complete (that is, when the active toolchain is missing), so it's absolutely bad news for anyone who wish this command could run faster.

[ChrisDenton]

Or rustup set auto-install disable for people who prefer not to use environment variables.

[Kobzol]

Are there plans to flip the default in the future, or is it expected that the auto-install behavior will stay the default? If it is the latter, I think that it could still be worth it to optimize the manifest loading.

[ChrisDenton]

I personally would like to move towards it being the default but we tried that in 1.28.0 and it was not well received. So it'll likely we'll support at least some (perhaps more limited) form of auto-install for awhile yet.

So, speaking for myself, I think it may be worth optimising the happy path if someone wants to work on that. But other team members may have other opinions.

[djc]

Are there plans to flip the default in the future, or is it expected that the auto-install behavior will stay the default? If it is the latter, I think that it could still be worth it to optimize the manifest loading.

I would say there are plans to flip the default, but I think none of us are currently very motivated to push the issue forward.

[Kobzol]

I tried to switch the loading to JSON, and with that running ./rustup which rustc takes ~20ms on my machine (vs ~40ms previously), out of which a large portion is building the regex for tracing-subscriber, which should be fixed with tokio-rs/tracing#3243 (to be backported in tokio-rs/tracing#3283). I noticed that there was already an attempt to optimize this in #2627, but it wasn't merged, so not sure how this will work out, but anyway - here's the PR: #4344.