Piping is extremely slow

[V0ldek]

Describe the bug

Piping when in nushell can be an order of magnitude slower than an equivalent piped command in bash. High-throughput commands on my machine suffer a slowdown of up to 50x when compared to similar redirects in bash or raw IO (for example redirecting to file vs. a binary that writes to the file itself).

How to reproduce

I used this Rust code to perform the measurements:

use std::io::{stdout, Write};
use std::time::{Duration, Instant};

const BUF_SIZE: usize = 8 * 1024;
const WRITE_CNT: usize = 8 * 1024;
const BYTES_LEN: usize = BUF_SIZE * WRITE_CNT;
const SAMPLES: usize = 15;

const BUF: [u8; BUF_SIZE] = [0xFF; BUF_SIZE];

fn main() {
    let mut stdout = stdout().lock();

    let mut samples: Vec<_> = (0..SAMPLES).map(|_| run(&mut stdout)).collect();
    samples.sort();

    let min = samples[0];
    let max = samples[SAMPLES - 1];
    let med = samples[SAMPLES / 2];

    eprintln!("Elapsed: [{min:?}, {med:?}, {max:?}]");
    eprintln!(
        "Throughput: [{:.2} MB/s, {:.2} MB/s, {:.2} MB/s]",
        thpt(min),
        thpt(med),
        thpt(max)
    );
}

fn run<W: Write>(out: &mut W) -> Duration {
    let start = Instant::now();
    for _ in 0..WRITE_CNT {
        out.write_all(&BUF).unwrap();
    }

    start.elapsed()
}

fn thpt(duration: Duration) -> f64 {
    (BYTES_LEN as f64 / 1000000.0) / duration.as_secs_f64()
}

It writes 64MBs of bytes in buffers of 8KB into its standard output and measures the time it takes. We measure 15 samples to remove spurious results, and print min, median, and max results/

The overhead is most visible if the receiver of the output has high throughput – /dev/null is hard to beat for that.

nushell

$ ./target/release/out-thpt out> /dev/null
Elapsed: [275.3485ms, 364.661123ms, 416.359778ms]
Throughput: [243.72 MB/s, 184.03 MB/s, 161.18 MB/s]

bash

$ ./target/release/out-thpt > /dev/null
Elapsed: [3.679879ms, 5.63634ms, 11.30741ms]
Throughput: [18236.70 MB/s, 11906.46 MB/s, 5934.95 MB/s]

When writing to files the same effect is seen, but with a smaller difference:

nushell

$ ./target/release/out-thpt | save out.txt -f
Elapsed: [280.598264ms, 298.941421ms, 538.216298ms]
Throughput: [239.16 MB/s, 224.49 MB/s, 124.69 MB/s]

bash

$ ./target/release/out-thpt > out.txt
Elapsed: [81.644023ms, 82.946274ms, 85.552982ms]
Throughput: [821.97 MB/s, 809.06 MB/s, 784.41 MB/s]

Another, more useful example: piping the results to a high-throughput tool like ripgrep:

nushell

$ ./target/release/out-thpt | rg 'x'
Elapsed: [190.961775ms, 278.648481ms, 652.648382ms]
Throughput: [351.43 MB/s, 240.84 MB/s, 102.83 MB/s]

bash

$ ./target/release/out-thpt | rg 'x'
Elapsed: [24.366165ms, 62.707143ms, 381.635499ms]
Throughput: [2754.18 MB/s, 1070.19 MB/s, 175.85 MB/s]

Expected behavior

I would expect nu to perhaps have some overhead on piping, but the level of 5x, 10x, 100x slowdown is very harsh when working with large datasets.

It also creates a very unexpected slowdown when writing to file. It's suddenly much worse to use the shell's redirect to a file than a commands builtin file output (if such exists).

Screenshots

No response

Configuration

version | transpose key value | to md --pretty

key	value
version	0.83.1
branch
commit_hash
build_os	linux-x86_64
build_target	x86_64-unknown-linux-gnu
rust_version	rustc 1.71.0 (8ede3aae2 2023-07-12)
rust_channel	stable-x86_64-unknown-linux-gnu
cargo_version	cargo 1.71.0 (cfd3bbd8f 2023-06-08)
build_time	2023-08-03 13:53:50 +01:00
build_rust_channel	release
allocator	standard
features	default, sqlite, trash, which, zip
installed_plugins

Additional context

No response

[sophiajt]

Would be nice to find when this regression happened. When we first added piping, we tested against systems like bash and external-to-external performance was comparable. It's been a few years since we did that test, though.

[amtoine]

not sure if anything has changed on that front but could you try with Nushell 0.86.0 or 0.86.1 @V0ldek ? 😇

[V0ldek]

not sure if anything has changed on that front but could you try with Nushell 0.86.0 or 0.86.1 @V0ldek ? 😇

Sure thing. Unfortunately, life happened and due to boring reasons I don't have access to the machine I ran the original tests on. But here's the comparison on a new (faster) one. I had v0.84.0 there, so I'm including that and the newest nushell I could get from crates.io (v0.86.0):

/dev/null

nushell (v0.84.0)

$ ./target/release/out-thpt out> /dev/null
Elapsed: [104.189532ms, 106.332611ms, 109.440512ms]
Throughput: [644.10 MB/s, 631.12 MB/s, 613.20 MB/s]

nushell (v0.86.0)

$ ./target/release/out-thpt out> /dev/null
Elapsed: [74.913097ms, 75.719376ms, 97.910004ms]
Throughput: [895.82 MB/s, 886.28 MB/s, 685.41 MB/s]

bash

$ ./target/release/out-thpt > /dev/null
Elapsed: [2.177211ms, 2.244449ms, 3.80449ms]
Throughput: [30823.32 MB/s, 29899.93 MB/s, 17639.39 MB/s]

File

nushell (v0.84.0)

$ ./target/release/out-thpt | save out.txt -f
Elapsed: [180.060344ms, 217.293486ms, 345.291572ms]
Throughput: [372.70 MB/s, 308.84 MB/s, 194.35 MB/s]

nushell (v0.86.0)

$ ./target/release/out-thpt | save out.txt -f
Elapsed: [157.707875ms, 159.822502ms, 287.39845ms]
Throughput: [425.53 MB/s, 419.90 MB/s, 233.50 MB/s]

bash

$ ./target/release/out-thpt > out.txt
Elapsed: [56.437486ms, 56.747906ms, 59.088127ms]
Throughput: [1189.08 MB/s, 1182.58 MB/s, 1135.74 MB/s]

ripgrep

nushell (v0.84.0)

$ ./target/release/out-thpt | rg 'x'
Elapsed: [72.738512ms, 94.279384ms, 317.48761ms]
Throughput: [922.60 MB/s, 711.81 MB/s, 211.37 MB/s]

nushell (v0.86.0)

$ ./target/release/out-thpt | rg 'x'
Elapsed: [73.575086ms, 80.786581ms, 321.982243ms]
Throughput: [912.11 MB/s, 830.69 MB/s, 208.42 MB/s]

bash

$ ./target/release/out-thpt | rg 'x'
Elapsed: [11.343015ms, 13.020561ms, 227.359305ms]
Throughput: [5916.32 MB/s, 5154.07 MB/s, 295.17 MB/s]

Looks like there's been some improvement between v0.84.0 and v0.86.0, but it's still way below the "baseline" of bash.

The new version | transpose key value | to md --pretty:

key	value
version	0.86.0
branch
commit_hash
build_os	linux-x86_64
build_target	x86_64-unknown-linux-gnu
rust_version	rustc 1.73.0 (cc66ad468 2023-10-03)
rust_channel	stable-x86_64-unknown-linux-gnu
cargo_version	cargo 1.73.0 (9c4383fb5 2023-08-26)
build_time	2023-10-21 17:18:13 +01:00
build_rust_channel	release
allocator	mimalloc
features	default, sqlite, trash, which, zip
installed_plugins

[yaksher]

I ran a reduced version of this benchmark (using the same code I just copy-pasted) on my new M3 MacBook.

The difference I observed is "only" 10x and not the 30x observed by the original poster, but nonetheless.

key	value
version	0.86.0
branch
commit_hash
build_os	macos-aarch64
build_target	aarch64-apple-darwin
rust_version	rustc 1.73.0 (cc66ad468 2023-10-03)
rust_channel	stable-aarch64-apple-darwin
cargo_version	cargo 1.73.0 (9c4383fb5 2023-08-26)
build_time	2023-10-26 00:25:34 -07:00
build_rust_channel	release
allocator	mimalloc
features	dataframe, default, sqlite, trash, which, zip
installed_plugins

Nushell:

$ ./target/release/throughput out> /dev/null
Elapsed: [100.3025ms, 101.858708ms, 116.751542ms]
Throughput: [669.06 MB/s, 658.84 MB/s, 574.80 MB/s]

Zsh:

% ./target/release/throughput > /dev/null
Elapsed: [5.073042ms, 5.839875ms, 10.926416ms]
Throughput: [13228.53 MB/s, 11491.49 MB/s, 6141.89 MB/s]