Performance regression when building with Nix and enabling the Nix experimental feature

[donvanderkrogt]

We are experiencing moderate to high performance regressions since upgrading to > 1.10.0. Our Nickel code base is relatively big and we see eval times increasing anywhere from 1-10x against the 1.9.1 Nickel version and this starts to impact productivity and developer experience. The eval times increased from ~ 100-300ms to 1-3secs depending on the eval target. I'm more than happy to look into this in more detail to identify root cause areas but decided to raise this issue as first step.

System

I am on a Apple M3 Pro running macOS 15.5

How to reproduce

I prepared a simple example to shows a ~3x slower eval time for relevant Nickel versions in the below script (note the first run is pretty cold when pulling in the relevant nixpkg revisions):

#!/usr/bin/env bash

declare -A versions=(
  ["1_9_1"]="028048884dc9517e548703beb24a11408cc51402"
  ["1_10_1"]="98b397fb30e0599c7460e9d3233a6ea51a07c371"
  ["1_11_0"]="2795c506fe8fb7b03c36ccb51f75b6df0ab2553f"
)

printf "Evaluating the following expression: \n"
tee t.ncl <<< 'let S = { _: String } in let t = import "t.json" in t | S'

nickel export -o s.json <<EOF
let S = 10 in
let T = (std.array.generate (std.function.const "0") S |> std.string.join "") in
std.array.range 0 1000 |> std.array.map(fun i => {"%{i |> std.to_string}" = T}) |> std.record.merge_all
EOF

command="nickel --version && hyperfine --warmup 5 'nickel eval t.ncl'"

for version in "${!versions[@]}"
  do
    rev=${versions[$version]}
    nix-shell -p nickel -p hyperfine -I nixpkgs="https://github.com/NixOS/nixpkgs/archive/$rev.tar.gz" --run "$command"
done

Which gives me the following output (cleaned)

Evaluating the following expression:
let S = { _: String } in let t = import "t.json" in t | S
nickel-lang-cli nickel 1.9.1 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      28.5 ms ±   6.3 ms    [User: 24.6 ms, System: 2.7 ms]
  Range (min … max):    26.2 ms …  75.7 ms    94 runs

nickel-lang-cli nickel 1.11.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      70.7 ms ±   4.0 ms    [User: 54.2 ms, System: 13.5 ms]
  Range (min … max):    67.3 ms …  89.5 ms    40 runs

nickel-lang-cli nickel 1.10.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      68.5 ms ±   5.5 ms    [User: 51.3 ms, System: 13.9 ms]
  Range (min … max):    65.0 ms …  93.1 ms    42 runs

[L0r3m1p5um]

It looks to me like this issue is issue is specific to the packaging in nixpkgs, and was introduced in this commit here: NixOS/nixpkgs@9918c46.

I modified your script a bit to run it against that nixpkgs version and its parent commit, and was able to reproduce the performance regression there. Both build from the 1.10.0 tag of nickel so the nickel version itself is identical.

Evaluating the following expression:
let S = { _: String } in let t = import "t.json" in t | S
Parent commit: 153ac89fba9f5f9e87690e46b214506da10ae4fd
nickel-lang-cli nickel 1.10.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      22.0 ms ±   0.6 ms    [User: 18.2 ms, System: 3.0 ms]
  Range (min … max):    21.1 ms …  24.0 ms    119 runs

nix-experimental enabled: 9918c46bd2c5ba1548b8de4a2acff36d9e127746
nickel-lang-cli nickel 1.10.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      31.4 ms ±   0.7 ms    [User: 25.1 ms, System: 5.0 ms]
  Range (min … max):    30.2 ms …  33.8 ms    89 runs

The difference in performance here is similar to what I was getting between 1.9.1 and 1.10.0 in your original script. I haven't been able to reproduce a significant difference in performance between newer versions and 1.9.1 when just building from source.

[L0r3m1p5um]

Maybe try this out? Setting enableNixImport to false when building the package makes it use the same configuration as before that commit. I'm getting better performance with 1.11.0 here compared to the default package. Unfortunately this build configuration isn't in the nix cache so it might take a while to build the first time.

nix-shell -p "nickel.override { enableNixImport = false; }" -p hyperfine -I nixpkgs="https://github.com/NixOS/nixpkgs/archive/2795c506fe8fb7b03c36ccb51f75b6df0ab2553f.tar.gz" --run "nickel --version && hyperfine --warmup 5 'nickel eval t.ncl'"

[yannham]

Thanks for the digging @L0r3m1p5um. While it sounds really strange that enabling the Nix FFI would impact code that doesn't use it in any measurable way, it also doesn't sound right that it's enabled by default on Nixpkgs, especially if it is the case that it does impact performance.

I'll try to reproduce on our MacOS builder soon. In the meantime, do you experience the same slowdown when using the prebuilt binaries for MacOS-arm64 available in the GitHub releases @donvanderkrogt ?

[donvanderkrogt]

@L0r3m1p5um I can indeed confirm that the regression completely disappears with the enableNixImport = false override.

@yannham I can also confirm that I do not experience the slowdown on the pre-build binaries. I modified my bash script slightly to show the delta eval time:

#!/usr/bin/env bash

declare -A versions=(
  # ["1.9.1"]="028048884dc9517e548703beb24a11408cc51402"
  ["1.10.0"]="98b397fb30e0599c7460e9d3233a6ea51a07c371"
  ["1.11.0"]="2795c506fe8fb7b03c36ccb51f75b6df0ab2553f"
)

printf "Evaluating the following expression: \n"
tee t.ncl <<< 'let S = { _: String } in let t = import "t.json" in t | S'

nickel export -o s.json <<EOF
let S = 10 in
let T = (std.array.generate (std.function.const "0") S |> std.string.join "") in
std.array.range 0 1000 |> std.array.map(fun i => {"%{i |> std.to_string}" = T}) |> std.record.merge_all
EOF

for version in "${!versions[@]}"
  do
    rev=${versions[$version]}
    nickel_bin="/tmp/nickel_$rev"
    wget "https://github.com/tweag/nickel/releases/download/$version/nickel-arm64-macos" -O "$nickel_bin"
    chmod +x "$nickel_bin"

    nix_build_command="nickel --version && hyperfine --warmup 5 'nickel eval t.ncl'"
    prebuild_build_command="$nickel_bin --version && hyperfine --warmup 5 '$nickel_bin eval t.ncl'"
    printf "Running Nix-build: \n"
    nix-shell -p nickel -p hyperfine -I nixpkgs="https://github.com/NixOS/nixpkgs/archive/$rev.tar.gz" --run "$nix_build_command"
    printf "Running pre-build: \n"
    nix-shell -p hyperfine --run "$prebuild_build_command"
done

Which gives me the following output:

Running Nix-build:
nickel-lang-cli nickel 1.10.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      66.9 ms ±   9.6 ms    [User: 49.6 ms, System: 13.2 ms]
  Range (min … max):    63.2 ms … 127.0 ms    42 runs

Running pre-build:
nickel-lang-cli nickel 1.10.0 (rev 4ba057b)
Benchmark 1: /tmp/nickel_98b397fb30e0599c7460e9d3233a6ea51a07c371 eval t.ncl
  Time (mean ± σ):      34.3 ms ±   5.7 ms    [User: 30.9 ms, System: 2.4 ms]
  Range (min … max):    31.8 ms …  71.3 ms    80 runs

Running Nix-build:
nickel-lang-cli nickel 1.11.0 (rev cargore)
Benchmark 1: nickel eval t.ncl
  Time (mean ± σ):      68.7 ms ±   2.3 ms    [User: 53.2 ms, System: 12.8 ms]
  Range (min … max):    65.8 ms …  76.1 ms    42 runs

Running pre-build:
nickel-lang-cli nickel 1.11.0 (rev 3c437b7)
Benchmark 1: /tmp/nickel_2795c506fe8fb7b03c36ccb51f75b6df0ab2553f eval t.ncl
  Time (mean ± σ):      32.3 ms ±   2.1 ms    [User: 29.2 ms, System: 2.3 ms]
  Range (min … max):    30.2 ms …  44.3 ms    86 runs

[yannham]

Thanks, that's good to know there wasn't any sneaky regression. Let's keep this issue open until it's at least fixed in Nixpkgs; will open a PR. I still wonder where the difference comes from. Could that be just a fixed constant added to the initialization time? That's the only plausible penalty I could see from enabling the Nix option.

[donvanderkrogt]

Thanks, that's good to know there wasn't any sneaky regression. Let's keep this issue open until it's at least fixed in Nixpkgs; will open a PR. I still wonder where the difference comes from. Could that be just a fixed constant added to the initialization time? That's the only plausible penalty I could see from enabling the Nix option.

For this simple case it seems like a fixed constant, though for a more complex eval target that we use, we get the following results:

Nix Build - nickel-lang-cli nickel 1.8.1 (rev cargore)
Benchmark 1: nickel export target.ncl
  Time (mean ± σ):      2.532 s ±  0.040 s    [User: 2.482 s, System: 0.047 s]
  Range (min … max):    2.441 s …  2.565 s    10 runs

Nix Build - nickel-lang-cli nickel 1.11.0 (rev cargore)
Benchmark 1: nickel export target.ncl
  Time (mean ± σ):     18.884 s ±  0.177 s    [User: 18.363 s, System: 0.484 s]
  Range (min … max):   18.625 s … 19.268 s    10 runs

Pre Build - nickel-lang-cli nickel 1.11.0 (rev cargore)
Benchmark 1: /tmp/nickel_98b397fb30e0599c7460e9d3233a6ea51a07c371 export target.ncl
  Time (mean ± σ):      3.119 s ±  0.042 s    [User: 3.060 s, System: 0.056 s]
  Range (min … max):    3.056 s …  3.178 s    10 runs

[yannham]

Thanks for the data. This is quite surprising, especially the drastic nature of the impact, so I'm leaving this issue open as long as the situation hasn't been clarified.

[jneem]

Can you share a longer-running input that demonstrates the slowdown? I did some quick profiling on the original example, but the only difference I saw in the --features=nix-experimental version was a lot of time spent in dynamic linking, which I guess would just be a fixed startup cost.