Unresolvable graphs don't give clear error messages

[nipunn1313]

Running cargo update is extremely slow on our project (taking minutes).
The project totals to 237 crates (including deps)
It looks like grep package Cargo.lock | wc -l gives 116.

According to top, the cargo process is running at 100% CPU.

$ cargo --version
cargo 0.20.0 (a60d185c8 2017-07-13)

I ran perf on it while it's running and got this output

+   28.86%    25.86%  cargo    cargo               [.] _$LT$cargo..core..resolver..Context$LT$$u27$a$GT$$u20$as$u20$core..clone..Clone$GT$::clone::h8d357b78d9e00e21
+   18.39%     0.00%  cargo    [unknown]           [.] 0x0000000000000001
+   15.64%     0.00%  cargo    [unknown]           [.] 0000000000000000
+    9.18%     9.06%  cargo    cargo               [.] core::ptr::drop_in_place::ha0fd95817afbc52e
+    9.01%     0.00%  cargo    [unknown]           [.] 0x00007f887f40c000
+    7.50%     7.50%  cargo    cargo               [.] mallocx
+    7.24%     7.24%  cargo    cargo               [.] arena_dalloc_bin_locked_impl.isra.42
+    7.23%     7.23%  cargo    cargo               [.] sdallocx
+    4.76%     0.00%  cargo    [unknown]           [.] 0x00000001ffffffff
+    4.60%     4.60%  cargo    cargo               [.] je_arena_tcache_fill_small
+    2.89%     2.89%  cargo    cargo               [.] cargo::core::resolver::DepsFrame::min_candidates::hce0dcb2c0b27c888
+    2.43%     2.43%  cargo    cargo               [.] core::ptr::drop_in_place::h96afb62de45b1f78
+    2.27%     2.27%  cargo    cargo               [.] _$LT$std..collections..hash..map..DefaultHasher$u20$as$u20$core..hash..Hasher$GT$::write::hc2b53c9fa13bdbbd
+    2.12%     0.00%  cargo    [unknown]           [.] 0x0000000000000007
+    1.97%     0.00%  cargo    [unknown]           [.] 0x00746c7561666564
+    1.84%     1.69%  cargo    cargo               [.] _$LT$collections..string..String$u20$as$u20$core..clone..Clone$GT$::clone::hafc1759e91f587ca
+    1.75%     1.70%  cargo    cargo               [.] core::ptr::drop_in_place::h64ab6067605e0684
+    1.44%     1.44%  cargo    cargo               [.] je_tcache_bin_flush_small
+    1.39%     0.00%  cargo    [unknown]           [.] 0x00007f887afb4310
+    1.26%     1.26%  cargo    cargo               [.] cargo::core::resolver::RemainingCandidates::next::he5bc3016627f0166
+    1.25%     1.24%  cargo    cargo               [.] cargo::core::resolver::activate_deps_loop::hac467bfc796b8a8f
+    1.09%     1.09%  cargo    cargo               [.] arena_run_tree_insert
+    0.97%     0.00%  cargo    [unknown]           [.] 0x00007f887f2c8f00
+    0.97%     0.89%  cargo    cargo               [.] cargo::core::resolver::Context::flag_activated::hcd2c1c559a35d134
+    0.96%     0.96%  cargo    cargo               [.] arena_run_tree_remove
+    0.95%     0.87%  cargo    cargo               [.] _$LT$std..collections..hash..table..RawTable$LT$K$C$$u20$V$GT$$GT$::new_uninitialized::h039223cfa7323d18
+    0.91%     0.91%  cargo    cargo               [.] std::collections::hash::table::calculate_allocation::habcebf8b74602154
+    0.86%     0.86%  cargo    libpthread-2.23.so  [.] pthread_mutex_lock
+    0.85%     0.85%  cargo    libpthread-2.23.so  [.] pthread_mutex_unlock
+    0.80%     0.60%  cargo    cargo               [.] core::ptr::drop_in_place::h39eafd2bca18bed7
+    0.79%     0.78%  cargo    cargo               [.] cargo::core::resolver::activate::h8f7013063d87cce6
+    0.79%     0.79%  cargo    cargo               [.] _$LT$std..collections..hash..map..DefaultHasher$u20$as$u20$core..hash..Hasher$GT$::finish::he8b0a85c016684d6
+    0.78%     0.78%  cargo    cargo               [.] _$LT$collections..binary_heap..BinaryHeap$LT$T$GT$$u20$as$u20$core..clone..Clone$GT$::clone::h7cb78581a77fd3be
+    0.73%     0.73%  cargo    cargo               [.] __rust_allocate
+    0.71%     0.71%  cargo    cargo               [.] _$LT$cargo..core..package_id..PackageId$u20$as$u20$core..cmp..PartialEq$GT$::eq::hfa3b45112fc5cba2
+    0.69%     0.68%  cargo    cargo               [.] core::ptr::drop_in_place::h606b1469d0cf5593
+    0.65%     0.00%  cargo    [unknown]           [.] 0xea544a63c24dc1eb
+    0.64%     0.64%  cargo    cargo               [.] core::ptr::drop_in_place::hd083d212f2e21af4
+    0.62%     0.62%  cargo    cargo               [.] __rust_deallocate
+    0.60%     0.60%  cargo    cargo               [.] cargo::core::resolver::Context::prev_active::hbd78ea1ad794007e

[alexcrichton]

Oh dear sounds bad!

Would it be possible to gist the Cargo.toml as well so I could profile locally and confirm fixes?

[nipunn1313]

For some background, we're currently building with bazel and use the Cargo.toml/Cargo.lock solely for vendoring. cargo vendor and cargo update are the only commands we use.

Here is a gist of the Cargo.toml we used. The Cargo.lock is not going to be too useful to you because it has a bunch of our crates in it, but we do have an existing Cargo.lock also checked in, though deleting the Cargo.lock doesn't affect the issue

https://gist.github.com/nipunn1313/e7a5569361555d70788ea10c3b8331d8

I played with it a bit more and found that it sometimes takes at least minutes (possibly infinite loop) at 100% CPU. I ran it 10 times and 7/10 times it hung, but the other 3/10 times it finished quickly (around 5 seconds at 100% CPU) with a rather confusing failure.

Here's output from one of each

nipunn@nipunn-dbx:~/src/server/rust$ cargo update
    Updating registry `https://github.com/rust-lang/crates.io-index`
error: failed to select a version for `kernel32-sys` (required by `named_pipe`):
all possible versions conflict with previously selected versions of `kernel32-sys`
  version 0.2.1 in use by kernel32-sys v0.2.1
  possible versions to select: 0.2.2
nipunn@nipunn-dbx:~/src/server/rust$ cargo update
    Updating registry `https://github.com/rust-lang/crates.io-index`

^C

Note that neither the Cargo.toml nor Cargo.lock reference a v0.2.1 of kernel32-sys anywhere

[alexcrichton]

Perfect! I'm able to reproduce locally, I'll see if I can help debug this in the near future.

[alexcrichton]

Hm I think that this may actually be a case of #4066 where this is an unresolvable resolution graph which Cargo just takes forever to reject. An example is:

• The root manifest locks time at 0.1.14
• The root manifest locks mysql at 11.3.1
• The mysql crate at 11.3.1 requires chrono = "~0.3"
• The only matching crate for this is chrono at 0.3.0 (0.3.1 is yanked)
• The chrono crate at 0.3.0 requires time = "^0.1.36"

That ends up being un-resolvable because time is previously locked at 0.1.14 and it's also required at 0.1.36, but Cargo only allows one version in the 0.1.* series. I think what crate actually shows up as the error (e.g. kernel32-sys in your error) is nondeterministic.

Would it be possible to change Cargo.toml to drop the = on dependencies and use a lock file to lock things instead?

[nipunn1313]

Yeah I think we can eliminate the = and rely on the Cargo.lock as source of truth for version hardening. I guess we were doing cargo update and looking at the error message to help us figure out which versions to manually update, but manually updating isn't that fun anyway.

It is pretty disconcerting to have it run 100% CPU effectively indefinitely and occasionally give you a nondetermistic error. We were pretty confused by the error as it was referring to a version of kernel32-sys which we weren't using. I think the output of cargo update was unfortunately not useful in all cases there. Hard pinning with "=" is making our life harder though. Good suggestion.

[alexcrichton]

Oh yeah Cargo's error messages on unresolvable resolution graphs are awful right now, and #4066 covers how it takes way too long for Cargo to reach such a conclusion. Definitely both bugs in Cargo!

[Eh2406]

Does the problem still reproduce with https://gist.github.com/nipunn1313/e7a5569361555d70788ea10c3b8331d8?

speedtest2>cargo +stable generate-lockfile
    Updating registry `https://github.com/rust-lang/crates.io-index`
   Resolving dependency graph...
^C

Yes!
Is it fixed?

speedtest2>cargo +nightly generate-lockfile
    Updating registry `https://github.com/rust-lang/crates.io-index`
error: failed to select a version for `time`.
    ... required by package `chrono v0.3.0`
    ... which is depended on by `mysql v11.3.1`
    ... which is depended on by `rust v0.0.1 (file:///C:/.../speedtest2)`
versions that meet the requirements `^0.1.36` are: 0.1.39, 0.1.38, 0.1.37, 0.1.36

all possible versions conflict with previously selected packages.

  previously selected package `time v0.1.34`
    ... which is depended on by `rust v0.0.1 (file:///C:/.../speedtest2)`

failed to select a version for `time` which could resolve this conflict

Did not take eavan second and clear error message.
So at least for this case both fixed. :-)

[alexcrichton]

🎉