default log format causes massive slowdown

[Radvendii]

When I run nix build commands with the default log format (bar), it's wayy slower than running with --log-format raw-with-logs

Notes

• how much it slows things down depends on the terminal. Some terminals (xterm) seem to have no slowdown at all, others (st) have a small slowdown, and others (konsole, gnome-terminal) have huge slowdowns.
• -L does not solve the problem
• 2 >&1 does not solve the problem, so it's not a problem of stderr not being buffered
• redirecting output to a file > log 2 > &1 does solve the problem
• playing around with strace a bit, i suspect that the problem is that the status bar gets refreshed frequently, even when nothing is actually changing.
• one problem with --log-format raw-with-logs is that it doesn't tell you which build a log came from, and they can be interspersed so it can be very hard to tell what's going on. This has nothing to do with the slowdown, so it's annoying that it can't be turned on separately.

Steps To Reproduce

1. nix build github:nixos/nix
2. time nix build --rebuild github:nixos/nix

   41m54s (on gnome-terminal)

3. time nix build --rebuild --log-format raw-with-logs github:nixos/nix

   24m39s (on gnome-terminal)

Expected behavior

There's a few things that would help address this problem:

• clear documentation. raw-with-logs isn't even a documented option
• big slowdown mode should be opt-in not opt-out
• at the least, it should be easier to opt-out. --log-format raw-with-logs on every command is rather cumbersome.
  • short form?
  • specify in nix.conf?
• there should be a way to have output that marks which build a log line came from, but without the status bar.

nix-env --version output nix-env (Nix) 2.15.1

[ConnorBaker]

Perhaps this is resolved on newer versions of nix? @Radvendii are you able to reproduce with something newer?

[connorbaker@nixos-desktop:~]$ nix-info --markdown --sandbox --host-os
 - system: `"x86_64-linux"`
 - host os: `Linux 6.8.9, NixOS, 24.05 (Uakari), 24.05.20240515.33d1e75`
 - multi-user?: `yes`
 - sandbox: `yes`
 - version: `nix-env (Nix) 2.22.1`
 - nixpkgs: `/nix/store/0qd773b63yg8435w8hpm13zqz7iipcbs-source`

[connorbaker@nixos-desktop:~]$ CMD="nix build github:nixos/nix/ef5c846e257e1e284ad47ed6be4308d190fe6531" && hyperfine --ignore-failure --setup "$CMD" "$CMD --rebuild"
Benchmark 1: nix build github:nixos/nix/ef5c846e257e1e284ad47ed6be4308d190fe6531 --rebuild
  Time (mean ± σ):     103.733 s ±  1.103 s    [User: 0.042 s, System: 0.016 s]
  Range (min … max):   101.893 s … 105.120 s    10 runs

  Warning: Ignoring non-zero exit code.

[connorbaker@nixos-desktop:~]$ CMD="nix build github:nixos/nix/ef5c846e257e1e284ad47ed6be4308d190fe6531" && hyperfine --ignore-failure --setup "$CMD" "$CMD --rebuild --log-format raw-with-logs"
Benchmark 1: nix build github:nixos/nix/ef5c846e257e1e284ad47ed6be4308d190fe6531 --rebuild --log-format raw-with-logs
  Time (mean ± σ):     104.588 s ±  2.330 s    [User: 0.040 s, System: 0.019 s]
  Range (min … max):   101.765 s … 108.764 s    10 runs

  Warning: Ignoring non-zero exit code.

[Radvendii]

After building, timing rebuilds

nix build --rebuild  11.47s user 7.26s system 0% cpu 46:18.30 total
nix build --rebuild --log-format raw-with-logs  1.72s user 3.40s system 0% cpu 39:21.84 total

On st building nix is 7minutes (15%) faster with raw-with-logs

idk how hyperfine works; are you sure it's not capturing the output or redirecting it to a file?

[Radvendii]

I looked at hyperfine a bit. Indeed it seems to swallow the program's stdout by default, which entirely removes the slowdown behaviour. You need to add the --show-output flag.

[YorikSar]

@Radvendii It looks like https://github.com/NixOS/nix/pull/11380 could have addressed this issue, but it seems nixos/nix is now not a great test for it since it's a wrapper derivation. Could you check if this is still reproducible?