Performance regression in 1.64+ when BufReader inner reader doesn't fill the buffer

@rustbot

Code

I tried this code:

use std::cmp::min;
use std::io;

const TOTAL_BYTES: usize = 16 * 1024 * 1024;
// runtime increases as the difference between these values increases
const BYTES_PER_READ: usize = 8 * 1024;
const BUFREADER_CAPACITY: usize = 256 * 1024;

fn main() {
    let mut reader = io::BufReader::with_capacity(BUFREADER_CAPACITY, Reader(TOTAL_BYTES));
    let count = io::copy(&mut reader, &mut io::sink()).unwrap();
    println!("copied {count} bytes");
}

struct Reader(usize);

impl io::Read for Reader {
    fn read(&mut self, buf: &mut [u8]) -> io::Result<usize> {
        let len = min(min(buf.len(), self.0), BYTES_PER_READ);
        if len > 0 {
            buf[..len].copy_from_slice(&vec![0; len]);
            self.0 -= len;
        }
        Ok(len)
    }
}

I expected to see this happen:

$ rustc -o slowio slowio.rs
$ time ./slowio
copied 16777216 bytes

real	0m0.015s
user	0m0.011s
sys	0m0.003s

Instead, this happened:

$ rustc -o slowio slowio.rs
$ time ./slowio 
copied 16777216 bytes

real	0m8.909s
user	0m8.891s
sys	0m0.002s

The problem doesn't occur with optimization enabled.

Version it worked on

It most recently worked on:

rustc 1.63.0 (4b91a6ea7 2022-08-08)
binary: rustc
commit-hash: 4b91a6ea7258a947e59c6522cd5898e7c0a6a88f
commit-date: 2022-08-08
host: x86_64-unknown-linux-gnu
release: 1.63.0
LLVM version: 14.0.5

Version with regression

rustc 1.64.0 (Fedora 1.64.0-1.fc36)
binary: rustc
commit-hash: unknown
commit-date: unknown
host: x86_64-unknown-linux-gnu
release: 1.64.0
LLVM version: 14.0.5

Also fails on:

rustc 1.66.0-nightly (01af5040f 2022-10-04)
binary: rustc
commit-hash: 01af5040fdada6ef8f1b749cda798d80a8590b2c
commit-date: 2022-10-04
host: x86_64-unknown-linux-gnu
release: 1.66.0-nightly
LLVM version: 15.0.2

@rustbot modify labels: +regression-from-stable-to-stable -regression-untriaged

Thanks for reporting this! This is an issue with a debug build so it's unlikely to be prioritized high but I'm interested in helping out because this is very goofy.

The slow code here is the Iterator impl on slices. I think in the last stable release we switched the implementation of BufReader to eventually use ReadBuf, and the slow code is ReadBuf initializing the remaining uninitialized capacity. It does this by iterating over a slice, and that iteration is the slow bit.

What I don't get here is why we need to initialize at all. That doesn't seem right.

@rustbot

WG-prioritization assigning highest priority since this looks a pretty visible runtime perf. regression (Zulip discussion). If the assessment should be revised, please feel free to comment.

@rustbot label -I-prioritize +P-critical i-slow

I've tried bisecting with cargo bisect and feeding this command: rustc main.rs && timeout 2 ./main.

Regression seems to be in 50166d5 and confirm #98748

bisected with cargo-bisect-rustc v0.6.0

Host triple: x86_64-unknown-linux-gnu
Reproduce with:

cargo bisect-rustc ./script.sh --start 2022-07-01 --preserve

😂 I was so sure this wasn't my fault. More fool me for not bisecting it myself.

(This probably shows an opportunity to add a benchmark to the newly-established "runtime benchmarks" (rather than the compilation-time benchmarks that perf.rlo has classically focused on...)

After sleeping on this, I realized that there's no real reason to expect the worlds-worst-memset code which is the source of the slowdown to be totally optimized out with --release. And of course it isn't. This is also a substantial regression with optimizations. Here's a version of the original program that's touched up a bit:

use std::cmp::min;
use std::io;

const TOTAL_BYTES: usize = 16 * 1024 * 1024;
// runtime increases as the difference between these values increases
const BYTES_PER_READ: usize = 8 * 1024;
const BUFREADER_CAPACITY: usize = 256 * 1024;

fn main() {
    for _ in 0..1_000 {
        let mut reader = io::BufReader::with_capacity(BUFREADER_CAPACITY, Reader(TOTAL_BYTES));
        let count = io::copy(&mut reader, &mut io::sink()).unwrap();
        assert_eq!(count, 16777216)
    }
}

struct Reader(usize);

impl io::Read for Reader {
    fn read(&mut self, buf: &mut [u8]) -> io::Result<usize> {
        let len = min(min(buf.len(), self.0), BYTES_PER_READ);
        if len > 0 {
            buf[..len].copy_from_slice(&vec![0; len]);
            self.0 -= len;
        }
        Ok(len)
    }
}

On 1.63 I see runtime ~0.43 s, and on 1.64 ~4.8 s. So we have a slowdown of around 10x, though I suspect that number could be ratcheted up higher.

@rustbot

@rustbot claim

Rollup merge of rust-lang#102760 - saethlin:dont-reinit-buffer, r=Mar…

Awesome, thanks for the really quick fix!

Rollup merge of rust-lang#102811 - the8472:bufread-memset, r=m-ou-se

Rollup merge of #102760 - saethlin:dont-reinit-buffer, r=Mark-Simulacrum

Navigation Menu

Repository navigation

Performance regression in 1.64+ when `BufReader` inner reader doesn't fill the buffer #102727

Code

Version it worked on

Version with regression

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Performance regression in 1.64+ when BufReader inner reader doesn't fill the buffer #102727

Description

Code

Version it worked on

Version with regression

Activity

saethlin commented on Oct 6, 2022

apiraino commented on Oct 6, 2022

apiraino commented on Oct 6, 2022

saethlin commented on Oct 6, 2022

pnkfelix commented on Oct 6, 2022

saethlin commented on Oct 6, 2022

saethlin commented on Oct 6, 2022

bgilbert commented on Oct 9, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Performance regression in 1.64+ when `BufReader` inner reader doesn't fill the buffer #102727