Performance regression on nightly (when using Cursor::read_exact and Byteorder)

[pgkos]

The Rust compiler on nightly nightly-x86_64-unknown-linux-gnu rustc 1.25.0-nightly (61452e506 2018-01-09) outputs suboptimal code (when compiling using cargo build --release) for the following example - it does not inline Cursor::read_exact:

extern crate byteorder;

use std::io::Cursor;
use byteorder::{ByteOrder, ReadBytesExt, WriteBytesExt, BigEndian, LittleEndian};

fn main() {
    let buf: [u8; 4] = [1, 2, 3, 4];
    let mut cur = Cursor::new(&buf);

    println!("{}", cur.read_u8().unwrap());
    println!("{}", cur.read_u8().unwrap());
    println!("{}", cur.read_u8().unwrap());
    println!("{}", cur.read_u8().unwrap());
}

It outputs the following x86_64 code:

0x00007370      4157           push r15
0x00007372      4156           push r14
0x00007374      4155           push r13
0x00007376      4154           push r12
0x00007378      53             push rbx
0x00007379      4883ec70       sub rsp, 0x70
0x0000737d      c744245c0102.  mov dword [local_5ch], 0x4030201
0x00007385      488d44245c     lea rax, qword [local_5ch]
0x0000738a      4889442460     mov qword [local_60h], rax
0x0000738f      48c744246800.  mov qword [local_68h], 0
0x00007398      c644240f00     mov byte [local_fh], 0
0x0000739d      4c8d742410     lea r14, qword [local_10h]
0x000073a2      488d742460     lea rsi, qword [local_60h]
0x000073a7      488d5c240f     lea rbx, qword [local_fh]
0x000073ac      b901000000     mov ecx, 1
0x000073b1      4c89f7         mov rdi, r14
0x000073b4      4889da         mov rdx, rbx
0x000073b7      e834040000     call sym._std::io::cursor::Cursor_T__as_std::io::Read_::read_exact::h1287815a4700b069
0x000073bc      807c241003     cmp byte [local_10h], 3
0x000073c1      0f85c4010000   jne 0x758b
0x000073c7      8a44240f       mov al, byte [local_fh]
0x000073cb      8844240f       mov byte [local_fh], al
0x000073cf      48895c2410     mov qword [local_10h], rbx
0x000073d4      4c8d3d15b404.  lea r15, qword sym.core::fmt::num::__impl_core::fmt::Display_for_u8_::fmt::h4ec6712cb0a2082e
0x000073db      4c897c2418     mov qword [local_18h], r15
0x000073e0      4c8d25597026.  lea r12, qword 0x0026e440
0x000073e7      4c89642428     mov qword [local_28h], r12
0x000073ec      48c744243002.  mov qword [local_30h], 2
0x000073f5      4c8d2d740105.  lea r13, qword 0x00057570
0x000073fc      4c896c2438     mov qword [local_38h], r13
0x00007401      48c744244001.  mov qword [local_40h], 1
0x0000740a      4c89742448     mov qword [local_48h], r14
0x0000740f      48c744245001.  mov qword [local_50h], 1
0x00007418      488d7c2428     lea rdi, qword [local_28h]
0x0000741d      e8be8a0000     call sym.std::io::stdio::_print::h7a1dc186f4ac9af9
0x00007422      c644240f00     mov byte [local_fh], 0
0x00007427      4c8d742410     lea r14, qword [local_10h]
0x0000742c      488d742460     lea rsi, qword [local_60h]
0x00007431      488d5c240f     lea rbx, qword [local_fh]
0x00007436      b901000000     mov ecx, 1
0x0000743b      4c89f7         mov rdi, r14
0x0000743e      4889da         mov rdx, rbx
0x00007441      e8aa030000     call sym._std::io::cursor::Cursor_T__as_std::io::Read_::read_exact::h1287815a4700b069
0x00007446      807c241003     cmp byte [local_10h], 3
0x0000744b      0f853a010000   jne 0x758b
0x00007451      8a44240f       mov al, byte [local_fh]
0x00007455      8844240f       mov byte [local_fh], al
0x00007459      48895c2410     mov qword [local_10h], rbx
0x0000745e      4c897c2418     mov qword [local_18h], r15
0x00007463      4c89642428     mov qword [local_28h], r12
0x00007468      48c744243002.  mov qword [local_30h], 2
0x00007471      4c896c2438     mov qword [local_38h], r13
0x00007476      48c744244001.  mov qword [local_40h], 1
0x0000747f      4c89742448     mov qword [local_48h], r14
0x00007484      48c744245001.  mov qword [local_50h], 1
0x0000748d      488d7c2428     lea rdi, qword [local_28h]
0x00007492      e8498a0000     call sym.std::io::stdio::_print::h7a1dc186f4ac9af9
0x00007497      c644240f00     mov byte [local_fh], 0
0x0000749c      4c8d742410     lea r14, qword [local_10h]
0x000074a1      488d742460     lea rsi, qword [local_60h]
0x000074a6      488d5c240f     lea rbx, qword [local_fh]
0x000074ab      b901000000     mov ecx, 1
0x000074b0      4c89f7         mov rdi, r14
0x000074b3      4889da         mov rdx, rbx
0x000074b6      e835030000     call sym._std::io::cursor::Cursor_T__as_std::io::Read_::read_exact::h1287815a4700b069
0x000074bb      807c241003     cmp byte [local_10h], 3
0x000074c0      0f85c5000000   jne 0x758b
0x000074c6      8a44240f       mov al, byte [local_fh]
0x000074ca      8844240f       mov byte [local_fh], al
0x000074ce      48895c2410     mov qword [local_10h], rbx
0x000074d3      4c897c2418     mov qword [local_18h], r15
0x000074d8      4c89642428     mov qword [local_28h], r12
0x000074dd      48c744243002.  mov qword [local_30h], 2
0x000074e6      4c896c2438     mov qword [local_38h], r13
0x000074eb      48c744244001.  mov qword [local_40h], 1
0x000074f4      4c89742448     mov qword [local_48h], r14
0x000074f9      48c744245001.  mov qword [local_50h], 1
0x00007502      488d7c2428     lea rdi, qword [local_28h]
0x00007507      e8d4890000     call sym.std::io::stdio::_print::h7a1dc186f4ac9af9
0x0000750c      c644240f00     mov byte [local_fh], 0
0x00007511      4c8d742410     lea r14, qword [local_10h]
0x00007516      488d742460     lea rsi, qword [local_60h]
0x0000751b      488d5c240f     lea rbx, qword [local_fh]
0x00007520      b901000000     mov ecx, 1
0x00007525      4c89f7         mov rdi, r14
0x00007528      4889da         mov rdx, rbx
0x0000752b      e8c0020000     call sym._std::io::cursor::Cursor_T__as_std::io::Read_::read_exact::h1287815a4700b069
0x00007530      807c241003     cmp byte [local_10h], 3
0x00007535      7554           jne 0x758b
0x00007537      8a44240f       mov al, byte [local_fh]
0x0000753b      8844240f       mov byte [local_fh], al
0x0000753f      48895c2410     mov qword [local_10h], rbx
0x00007544      4c897c2418     mov qword [local_18h], r15
0x00007549      4c89642428     mov qword [local_28h], r12
0x0000754e      48c744243002.  mov qword [local_30h], 2
0x00007557      4c896c2438     mov qword [local_38h], r13
0x0000755c      48c744244001.  mov qword [local_40h], 1
0x00007565      4c89742448     mov qword [local_48h], r14
0x0000756a      48c744245001.  mov qword [local_50h], 1
0x00007573      488d7c2428     lea rdi, qword [local_28h]
0x00007578      e863890000     call sym.std::io::stdio::_print::h7a1dc186f4ac9af9
0x0000757d      4883c470       add rsp, 0x70
0x00007581      5b             pop rbx
0x00007582      415c           pop r12
0x00007584      415d           pop r13
0x00007586      415e           pop r14
0x00007588      415f           pop r15
0x0000758a      c3             ret

On stable (stable-x86_64-unknown-linux-gnu rustc 1.23.0 (766bd11c8 2018-01-01)), it outputs:

0x00007130      55             push rbp
0x00007131      4889e5         mov rbp, rsp
0x00007134      4157           push r15
0x00007136      4156           push r14
0x00007138      4155           push r13
0x0000713a      4154           push r12
0x0000713c      53             push rbx
0x0000713d      4883ec48       sub rsp, 0x48
0x00007141      c745d3010203.  mov dword [local_2dh], 0x4030201
0x00007148      c645d701       mov byte [local_29h], 1
0x0000714c      4c8d75d7       lea r14, qword [local_29h]
0x00007150      4c897590       mov qword [local_70h], r14
0x00007154      4c8d3df5d804.  lea r15, qword sym.core::fmt::num::__impl_core::fmt::Display_for_u8_::fmt::h34a102a58af0af3e
0x0000715b      4c897d98       mov qword [local_68h], r15
0x0000715f      4c8d250a4426.  lea r12, qword obj.ref.j
0x00007166      4c8965a0       mov qword [local_60h], r12
0x0000716a      48c745a80200.  mov qword [local_58h], 2
0x00007172      4c8d2d8fef04.  lea r13, qword obj.ref.k
0x00007179      4c896db0       mov qword [local_50h], r13
0x0000717d      48c745b80100.  mov qword [local_48h], 1
0x00007185      488d5d90       lea rbx, qword [local_70h]
0x00007189      48895dc0       mov qword [local_40h], rbx
0x0000718d      48c745c80100.  mov qword [local_38h], 1
0x00007195      488d7da0       lea rdi, qword [local_60h]
0x00007199      e8a2560000     call sym.std::io::stdio::_print::h0e1f1f38819db7ba
0x0000719e      c645d702       mov byte [local_29h], 2
0x000071a2      4c897590       mov qword [local_70h], r14
0x000071a6      4c897d98       mov qword [local_68h], r15
0x000071aa      4c8965a0       mov qword [local_60h], r12
0x000071ae      48c745a80200.  mov qword [local_58h], 2
0x000071b6      4c896db0       mov qword [local_50h], r13
0x000071ba      48c745b80100.  mov qword [local_48h], 1
0x000071c2      48895dc0       mov qword [local_40h], rbx
0x000071c6      48c745c80100.  mov qword [local_38h], 1
0x000071ce      488d7da0       lea rdi, qword [local_60h]
0x000071d2      e869560000     call sym.std::io::stdio::_print::h0e1f1f38819db7ba
0x000071d7      8a45d5         mov al, byte [local_2bh]
0x000071da      8845d7         mov byte [local_29h], al
0x000071dd      4c897590       mov qword [local_70h], r14
0x000071e1      4c897d98       mov qword [local_68h], r15
0x000071e5      4c8965a0       mov qword [local_60h], r12
0x000071e9      48c745a80200.  mov qword [local_58h], 2
0x000071f1      4c896db0       mov qword [local_50h], r13
0x000071f5      48c745b80100.  mov qword [local_48h], 1
0x000071fd      48895dc0       mov qword [local_40h], rbx
0x00007201      48c745c80100.  mov qword [local_38h], 1
0x00007209      488d7da0       lea rdi, qword [local_60h]
0x0000720d      e82e560000     call sym.std::io::stdio::_print::h0e1f1f38819db7ba
0x00007212      8a45d6         mov al, byte [local_2ah]
0x00007215      8845d7         mov byte [local_29h], al
0x00007218      4c897590       mov qword [local_70h], r14
0x0000721c      4c897d98       mov qword [local_68h], r15
0x00007220      4c8965a0       mov qword [local_60h], r12
0x00007224      48c745a80200.  mov qword [local_58h], 2
0x0000722c      4c896db0       mov qword [local_50h], r13
0x00007230      48c745b80100.  mov qword [local_48h], 1
0x00007238      48895dc0       mov qword [local_40h], rbx
0x0000723c      48c745c80100.  mov qword [local_38h], 1
0x00007244      488d7da0       lea rdi, qword [local_60h]
0x00007248      e8f3550000     call sym.std::io::stdio::_print::h0e1f1f38819db7ba
0x0000724d      4883c448       add rsp, 0x48
0x00007251      5b             pop rbx
0x00007252      415c           pop r12
0x00007254      415d           pop r13
0x00007256      415e           pop r14
0x00007258      415f           pop r15
0x0000725a      5d             pop rbp
0x0000725b      c3             ret

[alexcrichton]

I believe this is a result of #46910 where LLVM's making a different inlining decision in the ThinLTO phases than it previously did when everything was in one codegen unit. That PR was merged with prior knowledge that it would not yield a 100% across-the-board improvement in all cases. That being said, @pgkos did this slow down a larger application perhaps? If so do you have a more macro-like benchmark to poke around with?

[pgkos]

@alexcrichton yes, larger apps are also affected.

A simple benchmark:

extern crate byteorder;

use std::io::Cursor;
use byteorder::{ByteOrder, ReadBytesExt, WriteBytesExt, BigEndian, LittleEndian};

fn main() {
    const LEN: usize = 100000000;
    let mut buf: Vec<u8> = Vec::with_capacity(LEN);
    unsafe { buf.set_len(LEN); };

    let mut cur = Cursor::new(&buf);

    let mut b = 0u8;
    loop {
        if let Ok(n) = cur.read_u8() {
            b += n;
        } else {
            break;
        }
    }
    println!("{}", b);
}

On stable:

real    0m0,359s
user    0m0,359s
sys     0m0,000s

On nightly:

real    0m1,286s
user    0m1,283s
sys     0m0,003s

[alexcrichton]

@pgkos er yeah for any decision where the compiler says "I won't inline this" a benchmark can be crafted to show why it was a bad decision to do that for performance, but I'm curious if you saw this in a real-world application at some point? In that did something slow down to trigger this?

A solution could be to just tag the relevant method here #[inline] to give LLVM more of a nudge to inline it, but I'd be curious to learn more about the history here first.

[alexcrichton]

This was discussed during libs triage and the conclusion was that we're more than willing to have a PR for an inline annotation if necessary here!