flox installer on x86_64-darwin is slow

[ghudgins]

STR:

• be on darwin
• install from pkg

Result: 5 minute install times
Expected: <2 minute install times

Can reproduce on my x86 machine

[ghudgins]

+1 from user research

[aakropotkin]

+1 it was really slow.

[mkenigs]

Can you attach logs? They have timestamps so should help identify what's slow

[tomberek]

Needs more info

[ghudgins]

the customer sent us an overly edited log that has no insights (and we can't really ask again). and as these things go I now can't reproduce on my machine despite having seen the performance. so it's not consistent. I can close this but not feeling good about closing it given how bad i've seen it

[limeytexan]

Ran installer from command line on my mac mini and it took just under 2.5 minutes. Following are excerpts from the install.log calling out the start times for all the functions and any notably long actions. TL;DR the expensive ones are

• extracting /usr/local/share/nix/nix.tar.xz: 1:03 (xz is quite slow on intel)
• nix copy extracted store to /nix/store: 0:36
• rm -rf /usr/local/share/nix/nix: 0:17 (surprising!)
• env launchctl kickstart -k system/org.nixos.nix-daemon: 0:10
• nix store ping --store daemon: 0:07 (again surprising so slow to warm up)

2024-05-24 17:49:31+01 lhr-x86-64-darwin-01 installer[1460]: Product archive /private/tmp/./flox.x86_64-darwin.pkg trustLevel=350
...
2024-05-24 17:49:32+01 lhr-x86-64-darwin-01 installd[1461]: PackageKit: Extracting file:///tmp/flox.x86_64-darwin.pkg#flox-1.0.5.pkg (destination=/Library/InstallerSandboxes/.PKInstallSandboxManager/714F7A33-1C7B-4744-9DC5-4D7984AA3685.activeSandbox/Root, uid=0)
...
2024-05-24 17:49:33+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./preinstall: + set -e
...
2024-05-24 17:49:33+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./preinstall: + /nix/store/7vrl8xlqb5asv3lzm0f8nlhjriasb1fd-nix-2.17.0/bin/nix-store --add-root /usr/local/share/nix/old-nix -r /nix/store/7vrl8xlqb5asv3lzm0f8nlhjriasb1fd-nix-2.17.0
...
2024-05-24 17:49:33+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + set -euo pipefail
...
2024-05-24 17:49:33+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + . /usr/local/share/nix/scripts/flox-install-multi-user.sh
...
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_create_directories
...
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_place_channel_configuration
...
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_place_nix_configuration false
...
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_poly_poly_install_nix
...
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + tar -C / -xJpf /usr/local/share/nix/var.tar.xz --no-same-owner
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_copy_nix /usr/local/share/nix
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + local USR_NIX_DIR=/usr/local/share/nix
2024-05-24 17:49:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + tar -C /usr/local/share/nix -xJpf /usr/local/share/nix/nix.tar.xz --no-same-owner
2024-05-24 17:50:42+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + /usr/local/share/nix/old-nix/bin/nix --extra-experimental-features nix-command --option substitute false copy --from /usr/local/share/nix --all --no-check-sigs
2024-05-24 17:50:42+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: copying 91 paths...
2024-05-24 17:50:42+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: copying path '/nix/store/14f338gzwfm1n3735ihbh8is88gklx1c-zdotdir' to 'local'...
...
2024-05-24 17:51:18+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: copying path '/nix/store/0m3qgz6krmpch6w86fv84mcx8wp3m10r-channel-nixpkgs' to 'local'...
2024-05-24 17:51:18+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + dd if=/dev/null of=/usr/local/share/nix/nix.tar.xz
2024-05-24 17:51:18+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + rm -rf /usr/local/share/nix/nix
2024-05-24 17:51:35+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + rm -f /usr/local/share/nix/old-nix
...
2024-05-24 17:51:35+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_check_selinux
...
2024-05-24 17:51:35+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_poly_poly_configure_nix_daemon_service
...
2024-05-24 17:51:35+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_poly_configure_nix_daemon_service
...
2024-05-24 17:51:35+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + env launchctl kickstart -k system/org.nixos.nix-daemon
2024-05-24 17:51:45+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + is_os_darwin
...
2024-05-24 17:51:45+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_patch_darwin_files
...
2024-05-24 17:51:45+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + /usr/local/bin/nix --experimental-features nix-command store ping --store daemon
2024-05-24 17:51:53+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: Store URL: daemon
2024-05-24 17:51:53+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: Version: 2.17.1 
2024-05-24 17:51:53+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: Trusted: 0
...
2024-05-24 17:51:53+01 lhr-x86-64-darwin-01 package_script_service[1463]: Responsibility set back to self.
...
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]: **** Summary Information ****
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:   Operation      Elapsed time
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]: -----------------------------
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:        disk      0.02 seconds
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:      script      0.00 seconds
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:        zero      0.00 seconds
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:     install      142.85 seconds
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:     -total-      142.88 seconds
2024-05-24 17:51:54+01 lhr-x86-64-darwin-01 installer[1460]:

[limeytexan]

@mkenigs asked me to do a full uninstall and reinstall to see if that changed anything. TL;DR: it was 33 seconds faster for not having to merge contents with an existing /nix/store.

Similar analysis to the one above:

• mounting /nix/store: 0:10 (not required with previous install)
• create build users: 0:15 (not required with previous install)
• extracting /usr/local/share/nix/nix.tar.xz: 0:58 (xz is quite slow on intel)
• env launchctl kickstart -k system/org.nixos.nix-daemon: 0:10
• nix store ping --store daemon: 0:09 (again surprising so slow to warm up)

2024-05-25 12:54:36+01 lhr-x86-64-darwin-01 installer[18851]: Product archive /private/tmp/./flox.x86_64-darwin.pkg trustLevel=350
...
2024-05-25 12:54:38+01 lhr-x86-64-darwin-01 installd[1461]: PackageKit: Extracting file:///tmp/flox.x86_64-darwin.pkg#flox-1.0.5.pkg (destination=/Library/InstallerSandboxes/.PKInstallSandboxManager/2CFDEF39-B9D3-43CE-A4B8-73C4D7E1C45E.activeSandbox/Root, uid=0)
...
2024-05-25 12:54:39+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./preinstall: + set -e
...
2024-05-25 12:54:40+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + set -euo pipefail
...
2024-05-25 12:54:40+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + . /usr/local/share/nix/scripts/flox-install-multi-user.sh
...
2024-05-25 12:54:40+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_cure_artifacts
...
2024-05-25 12:54:40+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_validate_starting_assumptions
...
2024-05-25 12:54:40+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_poly_prepare_to_install
...
2024-05-25 12:54:42+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + env launchctl kickstart -k system/org.nixos.darwin-store
2024-05-25 12:54:52+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + await_volume
...
2024-05-25 12:54:52+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_create_build_group
...
2024-05-25 12:54:52+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_create_build_users
...
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_create_directories
...
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_place_channel_configuration
...
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_place_nix_configuration false
...
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_poly_poly_install_nix
...
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_extract_nix /usr/local/share/nix/nix.tar.xz
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + local XZ_PATH=/usr/local/share/nix/nix.tar.xz
2024-05-25 12:55:07+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + tar -C / -xJpf /usr/local/share/nix/nix.tar.xz --no-same-owner
2024-05-25 12:56:05+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + dd if=/dev/null of=/usr/local/share/nix/nix.tar.xz
...
2024-05-25 12:56:05+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_check_selinux
...
2024-05-25 12:56:06+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + env launchctl kickstart -k system/org.nixos.nix-daemon
2024-05-25 12:56:16+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + is_os_darwin
...
2024-05-25 12:56:16+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + flox_patch_darwin_files
...
2024-05-25 12:56:16+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: + /usr/local/bin/nix --experimental-features nix-command store ping --store daemon
2024-05-25 12:56:25+01 lhr-x86-64-darwin-01 package_script_service[1463]: ./postinstall: Store URL: daemon
...
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]: **** Summary Information ****
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:   Operation      Elapsed time
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]: -----------------------------
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:        disk      0.02 seconds
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:      script      0.01 seconds
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:        zero      0.00 seconds
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:     install      109.59 seconds
2024-05-25 12:56:26+01 lhr-x86-64-darwin-01 installer[18851]:     -total-      109.62 seconds