Crate graph resolution on parity-wasm with a lockfile is noticeably slow

[alexcrichton]

Following alexcrichton/cargo-vendor#89 I cloned the parity-ethereum repository and ran cargo build, but on subsequent tries, much to my surprise, it took a noticeably long time for Cargo to start printing "Compiling ..."!

This typically means that Cargo is spending too long in crate graph resolution, although it could be other things! Very unscientific testing shows ~.8s before "Compiling..." shows up on nightly. Interestingly CARGO_PROFILE=1 only shows ~100ms ms (!!) in resolution.

We may be able to do much better in this regard! cc @Eh2406, would you be curious to dig into this?

[Eh2406]

Thanks for the cc, I am happy to help. The next step IMO is to run the problematic invocation in a profiler perf/wpr and see where we are spending the time. I can't promise when I can get to reproducing hear.

[ehuss]

I took a quick look. It looks like there is a massive slowdown starting in 1.27. I don't think it is graph resolution, which is not significantly different. Things like build_unit_dependencies have had a huge increase in time (going from almost 0% to ~15% of the total time before first Compiling). I would guess it's the introduction of Profile to Unit, which I worried was a little heavy. I can continue digging around to get a better picture.

[ehuss]

I did some rough measurements of time-to-first-compile.

Version	Time
1.21	5.97s +/- 0.769 (!!!)
1.22	0.48s +/- 0.023
1.23	0.49s +/- 0.024
1.24	0.47s +/- 0.036
1.25	0.49s +/- 0.026
1.26	0.50s +/- 0.024
Just before Profiles(3b14988)	0.54s +/- 0.080
Profiles (c24a097)	0.60s +/- 0.025
1.27-stable	0.62s +/- 0.022
1.28-beta	0.65s +/- 0.059
1.29-nightly	0.63s +/- 0.059
master	0.63s +/- 0.026
master no profiles	0.62s +/- 0.035

The last one is a hacked version where I replaced Profile in Unit with &'static Profile and used a global profile and removed profile computation. I was surprised it didn't improve performance much. The patch is kinda big, so maybe it is due to some other reason.

There is a lot of variability due to caching. These numbers are after running once. The first run can be up to 2s before it starts. It's hard to nail down due to the variability.

It might be interesting to do more detailed profiling. About 0.15s of the startup time is updating git submodules. Resolve is about 0.15 to 0.2.

Not sure if this is helpful at all...

[alexcrichton]

Thanks for digging in @ehuss! My profile attempts on OSX didn't show the profile bits as being too much time, but I primarily saw:

I think the largest time here is basically spent in loading crates from the registry, which isn't uncommon for crates I've seen depending on lots of crates from crates.io

In that sense resolution itself may not be taking much time here, but rather things like reading the registry and parsing/walking git repositories (lots of git deps in this lock file)

[Eh2406]

Note that going from ~.50s -> ~0.6s is consistent with spending ~15% in build_unit_dependencies. And consistent with finding that we are spending most of our time in parsing the registry.

Not that I know how to make it faster.

[Eh2406]

I think this got worked on a lot since this issue, for example #6880 and #6867. Most of the profiling work here is now out of date. I will close this issue, we can open a new one if we find a new slow case.