Super-linear instantiation counts/time

[nagisa]

We have a fairly large workspace which in total pulls in approximately 900 dependencies IIRC. Running nix-instantiate Cargo.nix for that workspace takes minutes. Taking a look into it I found that it instantiates some crate derivations multiple times, sometimes tens of thousands of times!

   4503 instantiated 'rust_syn-1.0.14' -> '/nix/store/gw8q7d7sjk1m0h4i4flnmhfi0bc8pifa-rust_syn-1.0.14.drv'
   4799 instantiated 'rust_getrandom-0.1.14' -> '/nix/store/qi0zq2iib6j40hfafbrkj9zzfymlb186-rust_getrandom-0.1.14.drv'
   8374 instantiated 'rust_num-traits-0.2.11' -> '/nix/store/rir6x3zwh1r0gz0b8mpr5zmnjiqyx0z2-rust_num-traits-0.2.11.drv'
   8709 instantiated 'rust_cfg-if-0.1.10' -> '/nix/store/48bsy1kawm8k5sl0cj82cyr5ypfasjrx-rust_cfg-if-0.1.10.drv'
   9035 instantiated 'rust_libc-0.2.66' -> '/nix/store/56lnlnalmrfq3k7pzrjw543pidw6c2l2-rust_libc-0.2.66.drv'
  12914 instantiated 'rust_quote-1.0.2' -> '/nix/store/qw2k8q740mp7zv2xnbwqch1vhcz7b649-rust_quote-1.0.2.drv'
  14090 instantiated 'rust_autocfg-1.0.0' -> '/nix/store/flq0p6kpm4g6fvbxhpvkdiqcxqwyjhn7-rust_autocfg-1.0.0.drv'
  25809 instantiated 'rust_proc-macro2-1.0.8' -> '/nix/store/d00pj6n278m8ks6n6qykimxdd2gjdllc-rust_proc-macro2-1.0.8.drv'
  32272 instantiated 'rust_unicode-xid-0.2.0' -> '/nix/store/cb8abh74a2hnxjp7120c75hka3s2dxr4-rust_unicode-xid-0.2.0.drv

This issue can also be reproduced with smaller workspaces too! While it won’t take minutes to instantiate, you will still notice it being slow.

Reproducer

First, copy the following Cargo.toml file to somewhere:

[package]
name = "x"
version = "0.1.0"

[dependencies]
serde = { version = "1", features = ["derive"] }
failure = "0.1"
thiserror = "1"
structopt = "0.3"
derive_more = "0.99"
num-derive = "0.3"
html5ever = "0.25"
log = "0.4"
rand_core = "0.5"
serde_json = "1"
time = "0.2"
url = "2"
semver = "0.9"
toml = "0.5"
chrono = "0.4"
hyper = "0.13"
hyper-rustls = "0.19"
hyper-openssl = "0.8"
prometheus = "0.7"
yup-oauth2 = "4"
tonic = "0.1"
pyo3 = "0.8"
numpy = "0.7"
peroxide = "0.19.4"

Then run

# bash
cargo update
crate2nix generate
time nix-instantiate Cargo.nix -vvv 2>&1 >/dev/null | grep instantiated | sort | uniq -c | sort -h | tail -n 10

You should see something resembling the following output:

     78 instantiated 'rust_lazy_static-1.4.0' -> '/nix/store/jydym8n46zd7nyfb6hcyjl2lgsdlkkbk-rust_lazy_static-1.4.0.drv'
     80 instantiated 'rust_log-0.4.8' -> '/nix/store/bbc8vk9zb51rwjf3rd8n9337axgs27s1-rust_log-0.4.8.drv'
     90 instantiated 'rust_bytes-0.5.4' -> '/nix/store/pnxs5gg6vani6nvrksgdva9903qii88i-rust_bytes-0.5.4.drv'
     99 instantiated 'rust_slab-0.4.2' -> '/nix/store/7qm8gpyfil2pp2mar8x8ihyz2i8346q3-rust_slab-0.4.2.drv'
    175 instantiated 'rust_syn-1.0.14' -> '/nix/store/4wsyaj2bngw52jdy4fmz1s2x13g1iyqs-rust_syn-1.0.14.drv'
    190 instantiated 'rust_cfg-if-0.1.10' -> '/nix/store/4811bzvc8zidig9gnpf8ddq48mn0hwi9-rust_cfg-if-0.1.10.drv'
    270 instantiated 'rust_libc-0.2.66' -> '/nix/store/2ss6n4yqpgx7m13d4ry073fdqw6yxwb3-rust_libc-0.2.66.drv'
    351 instantiated 'rust_quote-1.0.2' -> '/nix/store/z9ifpss40fslb6db0w7hm4b1i83n4l4n-rust_quote-1.0.2.drv'
    696 instantiated 'rust_proc-macro2-1.0.8' -> '/nix/store/5zdy41ix0h0ygqh8f14wx97wd1fky4az-rust_proc-macro2-1.0.8.drv'
    872 instantiated 'rust_unicode-xid-0.2.0' -> '/nix/store/669nxgb9zzw5kvlprh3r0fnfqiga5sy0-rust_unicode-xid-0.2.0.drv'

real	0m3.121s
user	0m2.633s
sys	0m0.239s

---

I have no idea where to even begin looking or what could cause nix to re-instantiate the same crate many many times. It could be an issue inherent to nix, but as I’m not sure whether it is, I’ve reported it here first.

cc @andir

[kolloch]

Thanks for the report, especially the commands to reproduce.

Note that you are not specifying an attribute path, I think, therefore that might try to build the same thing in multiple ways. But interestingly enough, adding it does not change the paths in my test case (with the Cargo.nix from crate2nix).

I also don't know how much of this is expected. I'd expect that instantiations of the same drv are cheap but there seems to be at least an sqlite lookup for every instantiation which is wasteful.

Within the crate2nix code, I already attempted to memoize certain things. That said, obviously the same derivation will potentially appear multiple times in the dependency tree. That is expected. It would be interesting if the number of instantiations is at least proportional to the number that a dependency appears in the dependency tree.

FYI, I went with a slightly modified:

nix-instantiate -vvv ./crate2nix/Cargo.nix -A rootCrate.build 2>&1 >/dev/null | grep instantiated | sort | uniq -c | sort -nr | hea

(which shows the top contenders first)

[nagisa]

I went ahead and made a flamegraph of nix when evaluating a further cut-down Cargo.toml.

This suggests that most of the time is spent in build-rust-crate rather than the code generated by crate2nix... In particular https://github.com/NixOS/nixpkgs/blob/master/pkgs/build-support/rust/build-rust-crate/default.nix#L18 looks sketchy and also a likely culprit. cc @Ekleog @andir

[kolloch]

I don't have time right now but flamegraph did sound awesome! How did you create it? I want to play with that :)

With "looks sketchy", you mean that it is a hot spot? Maybe we can optimize but maybe it is also just called too often.

[andir]

@kolloch https://github.com/NixOS/nix/blob/2.3.1/contrib/stack-collapse.py that is probably how that was generated. The comments at the top of that script explain how you get there.

Just looking at the buildRustCrate code and at the fact that each line creates a new insert in the sqlite database my suspecion is the dep.override { … } which is done recursively for all deps of all deps of … https://github.com/NixOS/nixpkgs/blob/d6a8b55fb0fd9f41f3c83982a5e3a7b7d7a4f01f/pkgs/build-support/rust/build-rust-crate/default.nix#L66

That whole block doesn't really seem to be required for any of the current users of buildRustCrate. Neither carnix seems to really need that nor crate2nix requires that line.

Applying the following patch I was able to cut down the execution time and trace file size by a factor of roughly ten.

diff --git a/pkgs/build-support/rust/build-rust-crate/default.nix b/pkgs/build-support/rust/build-rust-crate/default.nix
index 569b48d25ae..f3a18161127 100644
--- a/pkgs/build-support/rust/build-rust-crate/default.nix
+++ b/pkgs/build-support/rust/build-rust-crate/default.nix
@@ -63,7 +63,7 @@ let crate = crate_ // (lib.attrByPath [ crate_.crateName ] (attr: {}) crateOverr
     buildTests_ = buildTests;
 
     # take a list of crates that we depend on and override them to fit our overrides, rustc, release, …
-    makeDependencies = map (dep: lib.getLib (dep.override { inherit release verbose crateOverrides; }));
+    makeDependencies = map (dep: lib.getLib dep);
 
     # crate2nix has a hack for the old bash based build script that did split
     # entries at `,`. No we have to work around that hack.

I'll try to investigate where that line actually originates from and if it is really superfluous.

[kolloch]

Wow, I am excited, that sounds awesome @andir!

[kolloch]

@andir's fix got merged!

I will close this for now but feel free to open another issue if you think that performance is still unacceptable.