Investigate why Solana is so slow.

[Eh2406]

Currently the Solana crates are filtered out of our test suite here. For some reason they take an extraordinarily long time to resolve (both for the existing resolver and even more so for PubGrub). It is not clear why they are difficult. Presumably they have some share dependency with some pattern that the resolvers do not like. What dependency, what pattern, we do not know. Perhaps if we had a smaller example that still exemplified the problematic behavior it would be easier to see the problem.

[Eh2406]

Here is the generated index file for one of the particularly problematic crates that was filtered out.
solana-core@1.3.5.ron.zip.

[Eh2406]

Focusing in on crates that had a high ratio of runtime to should cancel call count, pulled out the solana-transaction-status for investigation. After applying some minimization tools, here is a file that takes ~25s and is only 350k lines long. Which may or may not be useful to look at.
solana-transaction-status@1.3.17.ron.zip

Edit: solana-transaction-status@1.3.17 was fixed with 7d6a3f0

[x-hgg-x]

It seems that there is a lot a backtracking in the cargo resolver for specific versions of solana-core.

After checking the dependencies, I can see why:

• Each of the 78 versions of solana-core between 1.0.0 and 1.5.14 has a direct dependency to the other 20+ solana-X crates of the form ^1.x.y, where 1.x.y is the version of solana-core (this also applies for all solana-X crates before 1.5.14).
• Each of the 252 versions of solana-core between 1.5.15 and 1.18.25 has changed the format of the solana-X dependencies, which is now =1.x.y (this also applies for all solana-X crates after 1.5.15).

Since the resolver tries to get the most recent compatible version if possible, if we set solana-core = "=1.0.0" in a Cargo.toml the resolver will try all combinations of the 300+ versions for the 20+ solana crates without success, before finding a solution where all solana crates are at version 1.0.0. In my machine the resolution took almost 10min with cargo generate-lockfile, and 1m30s if I use -Zminimal-versions.

For versions 1.5.15 and above, the resolution is very fast since there is only one possible solution for the solana crates due to the = in the version requirement.

[Eh2406]

I guess I'm missing a detail, for versions <=1.5.14 what about the structure requires all the version numbers match?

The general question is can we find a smaller example that has the same reason for being slow? The easiest to debug are samples where every crate has a regular structure, and the overall runtime is exponential (or at least cubic) in the number of crates/versions. But those are hard to create from real-world examples. I've also been able to find the problem by identifying a small change that makes a big difference. Like "removing this one feature of one dependency of one crate makes things twice as fast" help me track down the solana-transaction-status@1.3.17 problem.

Looking at crates with a high -Zminimal-versions time to normal resolution time is a good idea I have not yet tried. Thanks.

[x-hgg-x]

By looking at the logs using CARGO_LOG='off,cargo::core::resolver::conflict_cache=debug', I managed to reproduce and minimize the slowdown. The main problem is that many versions of solana-crate-features have a dependency of cc = ^1.0.45 with the num_cpus feature, which is only available until cc v1.0.49 (see https://lib.rs/crates/cc/versions), so there is a lot of incompatibilities.

Here is a test showing this behavior:

#[test]
fn test() {
    let mut reg = Vec::new();

    const V: usize = 100;

    reg.push(pkg_dep_with(("cc", "1.0.0"), vec![], &[("f", &[])]));
    for v in 1..V {
        reg.push(pkg(("cc", format!("1.0.{v}"))));
    }

    reg.push(pkg_dep(
        ("solana-core", "1.0.0"),
        vec![
            dep("cc"), // resolve is instantaneous without this dependency
            dep_req("solana-1", "1.0.0"),
        ],
    ));

    const N: usize = 100;
    const C: usize = 3;

    for v in 0..N {
        let version = format!("1.0.{v}");
        for c in 1..C {
            reg.push(pkg_dep(
                (format!("solana-{c}"), &version),
                vec![dep_req(&format!("solana-{}", c + 1), &version)],
            ));
        }
        reg.push(pkg_dep(
            (format!("solana-{C}"), &version),
            vec![dep_req("cc", "1.0.0").with(&["f"])],
        ));
    }

    let deps = vec![dep("solana-core")];
    let res = resolve(deps, &reg).unwrap();
    println!("{:?}", res);
}

Here is the results with various values of C and N when V = 100, when running the test in release mode:
test-logs.tar.gz

With N = 99 the resolve is instantaneous, but with N = 100 it takes 12s, so there seems to be a threshold somewhere.

We can see that when C >= 2, the resolve time is linear over C but cubic over N:

	N=100	N=200	N=400
C=1	0.25s	0.5s	1.4s
C=2	7s	44s	314s
C=3	12s	77s	537s
C=6	30s	149s	1107s
C=12	99s	447s	2393s

When plugging these test cases in the SAT resolver, there is no slowdown at all: a solution is always found in less than 10ms.

Another thing: activate_deps_loop() is called in a loop in the resolver, and each time the conflict cache restart from zero since it is a local variable, so there is some duplicate work:
https://github.com/rust-lang/cargo/blob/aea3404eaea3f613a5f541abc1218b8eadd991ff/src/cargo/core/resolver/mod.rs#L140-L143.

[x-hgg-x]

When removing the cc dependency for solana-core, the resolve is instantaneous since it eliminates directly all versions of cc without the f feature.
When keeping this dependency, I think this is not possible because of feature unification.

[x-hgg-x]

(Note: I tried to run the sat resolver using infos from the solana-core@1.3.5.ron file, but the target platform for dependencies is missing in the file, so the generated summaries are invalid).

[x-hgg-x]

After more tests, it seems that the threshold occurs when N >= V.

So in the example above, setting V to 101 instead of 100 completely eliminates the slowdown, even if the number of candidate versions has increased.

[Eh2406]

That is very intriguing results! I wonder if similar slowdowns happen with the PubGrub based resolver from this crate.

(Note: I tried to run the sat resolver using infos from the solana-core@1.3.5.ron file, but the target platform for dependencies is missing in the file, so the generated summaries are invalid).

It is really unfortunate that we have two different testing infrastructures one here and one in Cargo's repo. I wonder how we could bring them closer to being inter-compatible.

After more tests, it seems that the threshold occurs when N >= V.

There are various heuristics that use "smallest number of candidates" to decide which requirements to resolve first. I wonder if that's why this cut off occurs.

[x-hgg-x]

After a quick perf, 70% of the time is spent hashing in this structure:
https://github.com/rust-lang/cargo/blob/ac39e69a0fff26f0b8c5e886c42175e8b58a6403/src/cargo/core/resolver/context.rs#L18-L29

[Eh2406]

I like to collect perf results with https://github.com/mstange/samply so that the results can be shared with just a few clicks.

[x-hgg-x]

Here is two perf profiles with C = 3 and N = 100 (read with https://profiler.firefox.com):
cargo.tar.gz
For the second profile I replaced the hasher with rustc-hash for the 4 fields in the ResolverContext of type im_rc::HashMap or im_rc::HashSet, and it shows a 60% decrease in resolution time.

[Eh2406]

That seems like an easy win! I look forward to your a PR to Cargo.

[x-hgg-x]

That is very intriguing results! I wonder if similar slowdowns happen with the PubGrub based resolver from this crate.

For this test it takes less than 2s to resolve using the PubGrub resolver with C = 12 and N = 400.

But I observe the same threshold when N >= V, and the same trend when N increases, but all resolution times are much smaller than with the current cargo resolver.