Strange perforamnce drops with const literals in closures

[idkravitz]

I asked about it on user.rust-lang.org and one user suggested that it may be a bug in optimizer indeed. So I should state that the things below are reproducable both in nightly and stable latest rust on x86_64-pc-windows-msvc triplet and x86_64-unknown-linux-gnu (tested inside WSL).

So our test subject would be the following snippet, that solves Max subarray problem

pub fn max_subarray_bad(arr: &[i32]) -> (usize, usize, i32)
{
    let prefixes = arr
        .iter()
        .enumerate()
        .scan((0, 0), |s, (i, v)| {
            if s.1 > 0 {
                s.1 = s.1 + *v;
            } else {
                *s = (i, *v);
            }
            Some(*s)
        });
    let (right_idx, (left_idx, sum)) = prefixes
        .enumerate()
        .max_by_key(|&(_, (_, sum))| sum)
        .unwrap();
    
    (left_idx, right_idx + 1, sum)
}

If we benchmark it with criterion crate with this benchmark code:

use criterion::{black_box, criterion_group, criterion_main, Criterion};

fn benchmark_linear(c: &mut Criterion) {
    const N: usize = 1000000;
    c.bench_function(&format!("max_subarray([..]) N = {}", N), |b| {
        b.iter(|| max_subarray::max_subarray_bad(black_box(&vec![0; N])))
    });
}

criterion_group!(benches, benchmark_linear);
criterion_main!(benches);

Then the output of cargo bench on my machine would be

Benchmarking max_subarray([..]) N = 1000000: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 16.6s or reduce sample count to 30.
max_subarray([..]) N = 1000000
                        time:   [3.2324 ms 3.2700 ms 3.3141 ms]
Found 10 outliers among 100 measurements (10.00%)
  6 (6.00%) high mild
  4 (4.00%) high severe

     Running target\release\deps\scratch-b68a42551ab01289.exe

But with the slight change of moving out 0 in expression s.1 > 0 in let binding outside of the closure can make a great difference. So the function is now this:

pub fn max_subarray_bad(arr: &[i32]) -> (usize, usize, i32)
{
    let zro = 0;
    let prefixes = arr
        .iter()
        .enumerate()
        .scan((0, 0), |s, (i, v)| {
            if s.1 > zro {
                s.1 = s.1 + *v;
            } else {
                *s = (i, *v);
            }
            Some(*s)
        });
    let (right_idx, (left_idx, sum)) = prefixes
        .enumerate()
        .max_by_key(|&(_, (_, sum))| sum)
        .unwrap();
    
    (left_idx, right_idx + 1, sum)
}

But cargo bench output indicates almost 20% performance gain!

Benchmarking max_subarray([..]) N = 1000000: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 12.9s or reduce sample count to 40.
max_subarray([..]) N = 1000000
                        time:   [2.5705 ms 2.5806 ms 2.5913 ms]
                        change: [-20.260% -19.668% -19.124%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe

     Running target\release\deps\scratch-b68a42551ab01289.exe

You can check that changing function back and forth with replacing 0 and zro in that expression indeed results in 20% performance change.

By the way, if we change let zro = 0 into const zro: i32 = 0 it results in performance drop too.

It looks like a bug in optimizer for me. Could someone verify it?

[panstromek]

OT hint - if you append triple backticks with a word rust like ```rust, github will highlight syntax 😉

[idkravitz]

OT hint - if you append triple backticks with a word rust like ```rust, github will highlight syntax

Thanks, I was wondering whats wrong with syntax highlight 👍

[idkravitz]

I also just checked it inside WSL with stable and nightly -x86_64-unknown-linux-gnu and the results were 33% performance difference on my machine.

[mati865]

It's not the optimizer: https://godbolt.org/z/LcLYaw

You can try disabling incremental compilation and reducing codegen-units to 1 to see if you can still reproduce it.

[idkravitz]

How weird indeed, if I disable incremental and set codegen-units to 1 both versions run in slowest time, but if I leave values at default the one with let runs in 20% faster.
In a case of incremental=false codegen-units=1:

Benchmarking max_subarray([..]) N = 1000000: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 16.7s or reduce sample count to 30.
max_subarray([..]) N = 1000000
                        time:   [3.3078 ms 3.3099 ms 3.3130 ms]
Found 12 outliers among 100 measurements (12.00%)
  2 (2.00%) low mild
  3 (3.00%) high mild
  7 (7.00%) high severe

Benchmarking max_subarray([..]) N = 1000000 #2: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 16.6s or reduce sample count to 30.
max_subarray([..]) N = 1000000 #2
                        time:   [3.2961 ms 3.2976 ms 3.2992 ms]
Found 10 outliers among 100 measurements (10.00%)
  6 (6.00%) high mild
  4 (4.00%) high severe

If I comment out profile settings in Cargo.toml, the output is:

Benchmarking max_subarray([..]) N = 1000000: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 17.1s or reduce sample count to 30.
max_subarray([..]) N = 1000000
                        time:   [3.3745 ms 3.3775 ms 3.3808 ms]
                        change: [+1.8443% +2.0076% +2.1392%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 11 outliers among 100 measurements (11.00%)
  5 (5.00%) high mild
  6 (6.00%) high severe

Benchmarking max_subarray([..]) N = 1000000 #2: Warming up for 3.0000 s
Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 13.4s or reduce sample count to 40.
max_subarray([..]) N = 1000000 #2
                        time:   [2.6242 ms 2.6262 ms 2.6286 ms]
                        change: [-20.425% -20.281% -20.087%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 8 outliers among 100 measurements (8.00%)
  4 (4.00%) high mild
  4 (4.00%) high severe

So the weird thing is, that I located that code-units=16 actually allow to produce more effective code for bench than code-units=1 (for the one with let bind)

BTW, rm -rf ./target doesn't change anything.
I made a setup crate for this issue, you can check it here

P.S. or it may be a bug in a criterion I didn't double checked the runtime with clock :)

[Kobzol]

It also might not be a bug at all, benchmarking such things is incredible tricky, you might get hit by code alignment issues or just sheer bad luck. When I benchmark the first function that you posted multiple times in a row, I sometimes get around 10 % differences (by running the SAME code). And as @mati685 posted, it seems to generate exactly the same assembly, as it should.

Really the only way to check what happens is for you to disassemble the two binaries produced on your system and check that the assembly is indeed the same. If it is, it's not a rustc issue :-)

Try compiling with debug symbols and then dissassemble the binaries for example with objdump -S -l to see if the assembly instructions match between the two versions.

[idkravitz]

Btw, the absolute same issue happens if I throw away criterion and use built-in test::Bencher (by same I mean it responds to code-units setting)

running 2 tests
tests::benchmark_bad  ... bench:   3,293,805 ns/iter (+/- 17,375)
tests::benchmark_good ... bench:   3,309,870 ns/iter (+/- 46,277)                                                                                                                                                                    
test result: ok. 0 passed; 0 failed; 0 ignored; 2 measured; 0 filtered out                                                                                                                                                                
C:\Users\idkra\dev\rust\issue-68632>cargo bench                                                                         
Compiling issue-68632 v0.1.0 (C:\Users\idkra\dev\rust\issue-68632)
    Finished bench [optimized] target(s) in 0.51s
     Running target\release\deps\issue_68632-80a8ccd9df83eb66.exe

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running target\release\deps\bench_builtin-30e90d201571b52f.exe

running 2 tests
test tests::benchmark_bad  ... bench:   3,375,950 ns/iter (+/- 32,356)
test tests::benchmark_good ... bench:   2,596,490 ns/iter (+/- 14,938)

test result: ok. 0 passed; 0 failed; 0 ignored; 2 measured; 0 filtered out

Try compiling with debug symbols and then dissassemble the binaries for example with objdump -S -l to see if the assembly instructions match between the two versions.

Well, its past-midnight in my TZ, so I'll dig into it tomorrow.

P.S.
I have tested this issue on two machines running Windows 10 and both reproduced it.

[idkravitz]

So as a last thing today, I made a simple binary crate with the following main.rs:

pub fn max_subarray_bad(arr: &[i32]) -> (usize, usize, i32)
{
    let zro: i32 = 0; // substitute let with const for slow version and vice versa
    let prefixes = arr
        .iter()
        .enumerate()
        .scan((0, 0), |s, (i, v)| {
            if s.1 > zro {
                s.1 = s.1 + *v;
            } else {
                *s = (i, *v);
            }
            Some(*s)
        });
    let (right_idx, (left_idx, sum)) = prefixes
        .enumerate()
        .max_by_key(|&(_, (_, sum))| sum)
        .unwrap();

    (left_idx, right_idx + 1, sum)
}

fn main() {
    const N: usize = 1000000;
    let v = vec![0; N];
    const loops: usize = 1000;
    let mut total_sum = 0;
    for i in 0..loops {
        let (_, _, sum) = max_subarray_bad(&v);
        total_sum += sum;
    }
    println!("{}", total_sum);
}

Then I compiled two versions with let and without and run time ./my_binary a few times. Here are my results:

$ time ../target/release/stupid-way
0

real    0m2.198s
user    0m2.188s
sys     0m0.000s
$ time ../target/release/stupid-way
0

real    0m2.195s
user    0m2.203s
sys     0m0.016s
$ time ../target/release/stupid-way
0

real    0m2.192s
user    0m2.188s
sys     0m0.000s
$ time ../target/release/stupid-way
0

real    0m2.188s
user    0m2.172s
sys     0m0.031s
$ time ../target/release/stupid-way
0

real    0m2.191s
user    0m2.172s
sys     0m0.000s

And for variant with let:

$ time ../target/release/stupid-way
0

real    0m1.409s
user    0m1.406s
sys     0m0.000s
$ time ../target/release/stupid-way
0

real    0m1.406s
user    0m1.391s
sys     0m0.016s
$ time ../target/release/stupid-way
0

real    0m1.404s
user    0m1.391s
sys     0m0.016s
$ time ../target/release/stupid-way
0

real    0m1.404s
user    0m1.391s
sys     0m0.016s
$ time ../target/release/stupid-way
0

real    0m1.405s
user    0m1.391s
sys     0m0.000s

As you can see the difference is significant and reproducable all the way

[idkravitz]

Good news: I localized that with debug=true, opt-level=3 and overflow-checks=false the issue is reproducable in my last code. If overflow-checks=true the issue isn't reproducable. So I'm glad that I would be able to disassemble with debug-info tomorrow.

Edit: I was shocked by codegen-units affecting it.
For codegen-units=16

real    0m2.803s
user    0m2.797s
sys     0m0.000s

For codegen-units=1

real    0m20.675s
user    0m20.656s
sys     0m0.016s

10 times performance drop!

[Kobzol]

I tried it too on my Linux notebook. If I use codegen-units=1, both binaries are completely equal (incremental compilation doesn't seem to make a difference). With the default setting there is indeed a difference between the compiled assembly.

With the constant it tests directly against zero, with the variable it compares the value with a register which holds the variable (this is unlikely to cause the difference, but it probably triggered a different codegen for something else).

However, since it produces equivalent code with codegen-units=1, I'm not sure if this is an actual issue.

[idkravitz]

@Kobzol try this snippet of main.rs:

pub fn max_subarray_bad(arr: &[i32]) -> (usize, usize, i32)
{
    let zro: i32 = 0;
    let prefixes = arr
        .iter()
        .enumerate()
        .scan((0, 0), |s, (i, v)| {
            if s.1 > zro {
                s.1 = s.1 + *v;
            } else {
                *s = (i, *v);
            }
            Some(*s)
        });
    let (right_idx, (left_idx, sum)) = prefixes
        .enumerate()
        .max_by_key(|&(_, (_, sum))| sum)
        .unwrap();

    (left_idx, right_idx + 1, sum)
}



fn main() {
    const N: usize = 1000000;
    let v = vec![0; N];
    const loops: usize = 2000;
    let mut total_sum = 0;
    for i in 0..loops {
        let (_, _, sum) = max_subarray_bad(&v);
        total_sum += sum;
    }
    println!("{}", total_sum);
}

With:

[profile.dev]
opt-level=3
debug=true
overflow-checks=false
codegen-units=1

and then set

codegen-units=16

Run the binary with time command, you'll see how drastically execution time changes without editing the source code. Thats clearly a bug

[Kobzol]

Well yes, when you change the number of codegen units, you are affecting the optimizer (more units = more parallelization, but possibly worse code). So if you increase the unit number (or use the default), the generated code can be slower, that is to be expected. For maximum performance you should use codegen-units=1 anyway.