Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Increasingly slow compilation as more levels of async are added in Rust 1.46 #75992

Open
nicholasbishop opened this issue Aug 27, 2020 · 105 comments · Fixed by #76928 or #78410
Open

Increasingly slow compilation as more levels of async are added in Rust 1.46 #75992

nicholasbishop opened this issue Aug 27, 2020 · 105 comments · Fixed by #76928 or #78410
Labels
A-async-await Area: Async & Await AsyncAwait-Triaged Async-await issues that have been triaged during a working group meeting. C-bug Category: This is a bug. E-needs-mcve Call for participation: This issue has a repro, but needs a Minimal Complete and Verifiable Example E-needs-test Call for participation: An issue has been fixed and does not reproduce, but no test has been added. I-compilemem Issue: Problems and improvements with respect to memory usage during compilation. I-compiletime Issue: Problems and improvements with respect to compile times. I-hang Issue: The compiler never terminates, due to infinite loops, deadlock, livelock, etc. ICEBreaker-Cleanup-Crew Helping to "clean up" bugs with minimal examples and bisections T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.

Comments

@nicholasbishop
Copy link
Contributor

I upgraded from 1.45 to 1.46 today and a crate I'm working on seems to hang forever while compiling. I've attempted to create a somewhat minimal test case. For convenience here's a repo that includes the code below: https://github.com/nicholasbishop/rust146hang

Cargo.toml:

[package]
name = "rust146hang"
version = "0.1.0"
edition = "2018"

[dependencies]
actix-web = "2.0"
bb8 = "0.4"
bb8-postgres = "0.4"
tokio-postgres = "0.5"

src/lib.rs:

use actix_web::{web, HttpResponse, Responder};
use bb8_postgres::PostgresConnectionManager;
use tokio_postgres::NoTls;

type Pool = bb8::Pool<PostgresConnectionManager<NoTls>>;

async fn handle_req_1(pool: &Pool) {
    let conn = pool.get().await.unwrap();
    conn.query_one("", &[]).await.unwrap();
}

async fn handle_req_2(pool: &Pool) {
    handle_req_1(pool).await;
}

async fn handle_req_3(pool: &Pool) {
    handle_req_2(pool).await;
}

async fn handle_req_4(pool: &Pool) {
    handle_req_3(pool).await;
}

async fn handle_req_5(pool: &Pool) {
    handle_req_4(pool).await;
}

async fn handle_req_final(pool: web::Data<Pool>) -> impl Responder {
    handle_req_5(pool.get_ref()).await;
    HttpResponse::Ok().finish()
}

pub fn app_config(config: &mut web::ServiceConfig) {
    config.service(
        web::scope("").route("/api", web::post().to(handle_req_final)),
    );
}

I've found that the slowness seems tied to the depth of the async call chain. In the example code I have a long call chain: handle_req_1 is called by handle_req_2 is called by handle_req_3, etc. Here's the compilation timing I've observed when changing handle_req_final to directly call one of the handle_req_N functions:

handle_req_1 -> 0m12s
handle_req_2 -> 0m28s
handle_req_3 -> 1m06s
handle_req_4 -> 2m18s
handle_req_5 -> 5m01s

These times only include building the rust146hang lib, not the dependencies.

(Caveat: unscientific timings, these are not averaged over multiple
runs or anything.)

$ cargo --version
cargo 1.46.0 (149022b1d 2020-07-17)
$ rustc --version
rustc 1.46.0 (04488afe3 2020-08-24)
@nicholasbishop nicholasbishop added the C-bug Category: This is a bug. label Aug 27, 2020
@jonas-schievink jonas-schievink added A-async-await Area: Async & Await I-compiletime Issue: Problems and improvements with respect to compile times. regression-from-stable-to-stable Performance or correctness regression from one stable version to another. labels Aug 27, 2020
@rustbot rustbot added the I-prioritize Issue: Indicates that prioritization has been requested for this issue. label Aug 27, 2020
@jyn514
Copy link
Member

jyn514 commented Aug 27, 2020

Possible duplicate of #72408?

@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 27, 2020

Noticed the same issue. A crate that compiled in 1.45 in about 4 minutes, seems to compile for forever in 1.46 (rustc utilized 100% of one core for at least 25minutes before I cancelled it)

EDIT: 2 hours of compilation later, and no result yet

@jonas-schievink jonas-schievink added the E-needs-bisection Call for participation: This issue needs bisection: https://github.com/rust-lang/cargo-bisect-rustc label Aug 27, 2020
@jyn514
Copy link
Member

jyn514 commented Aug 27, 2020

Interestingly, this only happens with cargo build, not cargo check.

@jonas-schievink jonas-schievink added the E-needs-mcve Call for participation: This issue has a repro, but needs a Minimal Complete and Verifiable Example label Aug 27, 2020
@estebank estebank added the T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. label Aug 27, 2020
@ojeda
Copy link
Contributor

ojeda commented Aug 27, 2020

Caveat: unscientific timings, these are not averaged over multiple runs or anything.

Well, it is a nearly perfect exponential fit!

@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 28, 2020

FYI, issue (remains) present in

  • rustc 1.46.0 (04488af 2020-08-24)
  • rustc 1.47.0-beta.1 (0f91f5c 2020-08-25)
  • rustc 1.48.0-nightly (397b390 2020-08-27)

It seems to not matter whether --release is set

@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 28, 2020

Got you an example on the playground (updated)

Just adjust the number for the macro call here:

async fn f() {
    //  9: ~0.68s
    // 10: ~0.83s
    // 11: ~1.34s
    // 12: ~2.68s
    // 13: ~5.24s reached length limit -> #![type_length_limit="1228764"]
    // 14: ~7.89s reached length limit -> #![type_length_limit="2457564"]
    // 15: /playground/tools/entrypoint.sh: line 11:     7 Killed                  timeout --signal=KILL ${timeout} "$@"
    async_recursive!(9, println!("done"))
}

EDIT: My crate that "compiles forever" just failed after nearly 3hours of compiling. I don't know what caused the SIGKILL, but it wasn't me at least.

$ time cargo test -p common --release

...
error: could not compile `messages`.

Caused by:
  process didn't exit successfully: `rustc --crate-name messages --edition=2018 messages/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi,artifacts --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 -C metadata=0c091483b2a87fc1 -C extra-filename=-0c091483b2a87fc1 --out-dir /tmp/cargo-target/release/deps -L dependency=/tmp/cargo-target/release/deps --extern asn1rs=/tmp/cargo-target/release/deps/libasn1rs-7f0d3cb210b4f673.rmeta --extern futures=/tmp/cargo-target/release/deps/libfutures-3a0be1c37a28e9a8.rmeta --extern serde=/tmp/cargo-target/release/deps/libserde-d9d8359d95432fa4.rmeta --extern serde_derive=/tmp/cargo-target/release/deps/libserde_derive-26bde9a45b227be1.so --extern tokio=/tmp/cargo-target/release/deps/libtokio-c76c350ce32195b9.rmeta --extern tokio_postgres=/tmp/cargo-target/release/deps/libtokio_postgres-e63ce98e1edc8138.rmeta` (signal: 9, SIGKILL: kill)

real    161m7,663s
user    169m13,774s
sys     0m35,055s

EDIT2: Updated example on the playground, old version
EDIT3: Updated example on the playground, old version
EDIT4: For your local testing

Create the file template.rs:

#![recursion_limit="2048"]
#![type_length_limit="12457564"]

macro_rules! async_recursive {
    (29, $inner:expr) => { async { async_recursive!(28, $inner) }.await };
    (28, $inner:expr) => { async { async_recursive!(27, $inner) }.await };
    (27, $inner:expr) => { async { async_recursive!(26, $inner) }.await };
    (26, $inner:expr) => { async { async_recursive!(25, $inner) }.await };
    (25, $inner:expr) => { async { async_recursive!(24, $inner) }.await };
    (24, $inner:expr) => { async { async_recursive!(23, $inner) }.await };
    (23, $inner:expr) => { async { async_recursive!(22, $inner) }.await };
    (22, $inner:expr) => { async { async_recursive!(21, $inner) }.await };
    (21, $inner:expr) => { async { async_recursive!(20, $inner) }.await };
    (20, $inner:expr) => { async { async_recursive!(19, $inner) }.await };

    (19, $inner:expr) => { async { async_recursive!(18, $inner) }.await };
    (18, $inner:expr) => { async { async_recursive!(17, $inner) }.await };
    (17, $inner:expr) => { async { async_recursive!(16, $inner) }.await };
    (16, $inner:expr) => { async { async_recursive!(15, $inner) }.await };
    (15, $inner:expr) => { async { async_recursive!(14, $inner) }.await };
    (14, $inner:expr) => { async { async_recursive!(13, $inner) }.await };
    (13, $inner:expr) => { async { async_recursive!(12, $inner) }.await };
    (12, $inner:expr) => { async { async_recursive!(11, $inner) }.await };
    (11, $inner:expr) => { async { async_recursive!(10, $inner) }.await };
    (10, $inner:expr) => { async { async_recursive!(9, $inner) }.await };

    (9, $inner:expr) => { async { async_recursive!(8, $inner) }.await };
    (8, $inner:expr) => { async { async_recursive!(7, $inner) }.await };
    (7, $inner:expr) => { async { async_recursive!(6, $inner) }.await };
    (6, $inner:expr) => { async { async_recursive!(5, $inner) }.await };
    (5, $inner:expr) => { async { async_recursive!(4, $inner) }.await };
    (4, $inner:expr) => { async { async_recursive!(3, $inner) }.await };
    (3, $inner:expr) => { async { async_recursive!(2, $inner) }.await };
    (2, $inner:expr) => { async { async_recursive!(1, $inner) }.await };
    (1, $inner:expr) => { async { async_recursive!(0, $inner) }.await };
    (0, $inner:expr) => { async { $inner }.await };
}

async fn f() {
    //  9: ~0.68s
    // 10: ~0.83s
    // 11: ~1.34s
    // 12: ~2.68s
    // 13: ~5.24s reached length limit -> #![type_length_limit="1228764"]
    // 14: ~7.89s reached length limit -> #![type_length_limit="2457564"]
    // 15: /playground/tools/entrypoint.sh: line 11:     7 Killed                  timeout --signal=KILL ${timeout} "$@"
    async_recursive!(REPLACE_ME, println!("done"))
}

fn main() {
    let _ = f();
}

Then run:

for n in $(seq 29); do sed "s/REPLACE_ME/$n/g" template.rs > main.rs && echo "== Level $n" && time rustc --edition 2018 main.rs; done
Sample output, looks exponential:
== Level 1

real	0m0,217s
user	0m0,149s
sys	0m0,038s
== Level 2

real	0m0,216s
user	0m0,169s
sys	0m0,039s
== Level 3

real	0m0,138s
user	0m0,132s
sys	0m0,017s
== Level 4

real	0m0,149s
user	0m0,129s
sys	0m0,029s
== Level 5

real	0m0,165s
user	0m0,127s
sys	0m0,047s
== Level 6

real	0m0,178s
user	0m0,165s
sys	0m0,022s
== Level 7

real	0m0,168s
user	0m0,141s
sys	0m0,035s
== Level 8

real	0m0,204s
user	0m0,178s
sys	0m0,038s
== Level 9

real	0m0,249s
user	0m0,214s
sys	0m0,046s
== Level 10

real	0m0,336s
user	0m0,319s
sys	0m0,028s
== Level 11

real	0m0,583s
user	0m0,575s
sys	0m0,016s
== Level 12

real	0m0,946s
user	0m0,927s
sys	0m0,030s
== Level 13

real	0m1,713s
user	0m1,674s
sys	0m0,036s
== Level 14

real	0m3,812s
user	0m3,667s
sys	0m0,079s
== Level 15

real	0m6,901s
user	0m6,807s
sys	0m0,055s
== Level 16

real	0m14,814s
user	0m14,599s
sys	0m0,156s
== Level 17

real	0m29,575s
user	0m28,952s
sys	0m0,312s
== Level 18

real	0m59,365s
user	0m58,339s
sys	0m0,800s

@jyn514 jyn514 removed the E-needs-mcve Call for participation: This issue has a repro, but needs a Minimal Complete and Verifiable Example label Aug 28, 2020
@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 28, 2020

Hmm, there might actually be two separate issues here? The example I provided above behaves the same on rustc 1.43.0 to current (1.42.0 and before are even slower). But the repo provided by @nicholasbishop and my local project compile fast on <=1.45.* and really slow with 1.46 and later.

@jyn514
Copy link
Member

jyn514 commented Aug 28, 2020

Sounds like the first example might be #72408, then.

@jyn514 jyn514 added the E-needs-mcve Call for participation: This issue has a repro, but needs a Minimal Complete and Verifiable Example label Aug 28, 2020
@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 28, 2020

I am able to somewhat limit it to argument parameters (being references! passing ownership has no effect).
In the following example the compilation time difference between 1.45 and 1.46 is about 2x.

Create the file template.rs:

#![recursion_limit="2048"]
#![type_length_limit="112457564"]

pub async fn h0(v: &String, x: &u64) { println!("{} {}", v, x) }
pub async fn h1(v: &String, x: &u64) { h0(v, x).await }
pub async fn h2(v: &String, x: &u64) { h1(v, x).await }
pub async fn h3(v: &String, x: &u64) { h2(v, x).await }
pub async fn h4(v: &String, x: &u64) { h3(v, x).await }
pub async fn h5(v: &String, x: &u64) { h4(v, x).await }
pub async fn h6(v: &String, x: &u64) { h5(v, x).await }
pub async fn h7(v: &String, x: &u64) { h6(v, x).await }
pub async fn h8(v: &String, x: &u64) { h7(v, x).await }
pub async fn h9(v: &String, x: &u64) { h8(v, x).await }

pub async fn h10(v: &String, x: &u64) { h9(v, x).await }
pub async fn h11(v: &String, x: &u64) { h10(v, x).await }
pub async fn h12(v: &String, x: &u64) { h11(v, x).await }
pub async fn h13(v: &String, x: &u64) { h12(v, x).await }
pub async fn h14(v: &String, x: &u64) { h13(v, x).await }
pub async fn h15(v: &String, x: &u64) { h14(v, x).await }
pub async fn h16(v: &String, x: &u64) { h15(v, x).await }
pub async fn h17(v: &String, x: &u64) { h16(v, x).await }
pub async fn h18(v: &String, x: &u64) { h17(v, x).await }
pub async fn h19(v: &String, x: &u64) { h18(v, x).await }


macro_rules! async_recursive {
    (29, $inner:expr) => { async { async_recursive!(28, $inner) }.await };
    (28, $inner:expr) => { async { async_recursive!(27, $inner) }.await };
    (27, $inner:expr) => { async { async_recursive!(26, $inner) }.await };
    (26, $inner:expr) => { async { async_recursive!(25, $inner) }.await };
    (25, $inner:expr) => { async { async_recursive!(24, $inner) }.await };
    (24, $inner:expr) => { async { async_recursive!(23, $inner) }.await };
    (23, $inner:expr) => { async { async_recursive!(22, $inner) }.await };
    (22, $inner:expr) => { async { async_recursive!(21, $inner) }.await };
    (21, $inner:expr) => { async { async_recursive!(20, $inner) }.await };
    (20, $inner:expr) => { async { async_recursive!(19, $inner) }.await };

    (19, $inner:expr) => { async { async_recursive!(18, $inner) }.await };
    (18, $inner:expr) => { async { async_recursive!(17, $inner) }.await };
    (17, $inner:expr) => { async { async_recursive!(16, $inner) }.await };
    (16, $inner:expr) => { async { async_recursive!(15, $inner) }.await };
    (15, $inner:expr) => { async { async_recursive!(14, $inner) }.await };
    (14, $inner:expr) => { async { async_recursive!(13, $inner) }.await };
    (13, $inner:expr) => { async { async_recursive!(12, $inner) }.await };
    (12, $inner:expr) => { async { async_recursive!(11, $inner) }.await };
    (11, $inner:expr) => { async { async_recursive!(10, $inner) }.await };
    (10, $inner:expr) => { async { async_recursive!(9, $inner) }.await };

    (9, $inner:expr) => { async { async_recursive!(8, $inner) }.await };
    (8, $inner:expr) => { async { async_recursive!(7, $inner) }.await };
    (7, $inner:expr) => { async { async_recursive!(6, $inner) }.await };
    (6, $inner:expr) => { async { async_recursive!(5, $inner) }.await };
    (5, $inner:expr) => { async { async_recursive!(4, $inner) }.await };
    (4, $inner:expr) => { async { async_recursive!(3, $inner) }.await };
    (3, $inner:expr) => { async { async_recursive!(2, $inner) }.await };
    (2, $inner:expr) => { async { async_recursive!(1, $inner) }.await };
    (1, $inner:expr) => { async { async_recursive!(0, $inner) }.await };
    (0, $inner:expr) => { async { h19(&String::from("owo"), &0).await; $inner }.await };
}

async fn f() {
    async_recursive!(REPLACE_ME, println!("hello"));
}

fn main() {
    let _ = f();
}

The execute:

for n in $(seq 15); do sed "s/REPLACE_ME/$n/g" template.rs > main.rs && echo && echo && echo && echo "== Level $n @ 1.45.0" && time rustc +1.45.0 --edition 2018 main.rs && echo "== Level $n @ 1.46.0" && time rustc --edition 2018 main.rs; done
Which results in:
== Level 1 @ 1.45.0

real	0m0,266s
user	0m0,241s
sys	0m0,037s
== Level 1 @ 1.46.0

real	0m0,181s
user	0m0,172s
sys	0m0,039s



== Level 2 @ 1.45.0

real	0m0,218s
user	0m0,212s
sys	0m0,045s
== Level 2 @ 1.46.0

real	0m0,182s
user	0m0,177s
sys	0m0,034s



== Level 3 @ 1.45.0

real	0m0,199s
user	0m0,179s
sys	0m0,051s
== Level 3 @ 1.46.0

real	0m0,191s
user	0m0,179s
sys	0m0,041s



== Level 4 @ 1.45.0

real	0m0,202s
user	0m0,197s
sys	0m0,035s
== Level 4 @ 1.46.0

real	0m0,213s
user	0m0,209s
sys	0m0,039s



== Level 5 @ 1.45.0

real	0m0,207s
user	0m0,212s
sys	0m0,024s
== Level 5 @ 1.46.0

real	0m0,206s
user	0m0,189s
sys	0m0,048s



== Level 6 @ 1.45.0

real	0m0,220s
user	0m0,206s
sys	0m0,044s
== Level 6 @ 1.46.0

real	0m0,230s
user	0m0,227s
sys	0m0,033s



== Level 7 @ 1.45.0

real	0m0,269s
user	0m0,251s
sys	0m0,048s
== Level 7 @ 1.46.0

real	0m0,271s
user	0m0,259s
sys	0m0,043s



== Level 8 @ 1.45.0

real	0m0,288s
user	0m0,260s
sys	0m0,059s
== Level 8 @ 1.46.0

real	0m0,373s
user	0m0,353s
sys	0m0,049s



== Level 9 @ 1.45.0

real	0m0,371s
user	0m0,368s
sys	0m0,034s
== Level 9 @ 1.46.0

real	0m0,540s
user	0m0,550s
sys	0m0,020s



== Level 10 @ 1.45.0

real	0m0,576s
user	0m0,583s
sys	0m0,024s
== Level 10 @ 1.46.0

real	0m0,860s
user	0m0,851s
sys	0m0,041s



== Level 11 @ 1.45.0

real	0m0,954s
user	0m0,941s
sys	0m0,044s
== Level 11 @ 1.46.0

real	0m1,588s
user	0m1,581s
sys	0m0,036s



== Level 12 @ 1.45.0

real	0m1,721s
user	0m1,696s
sys	0m0,040s
== Level 12 @ 1.46.0

real	0m3,168s
user	0m3,122s
sys	0m0,057s



== Level 13 @ 1.45.0

real	0m3,406s
user	0m3,329s
sys	0m0,070s
== Level 13 @ 1.46.0

real	0m5,861s
user	0m5,831s
sys	0m0,044s



== Level 14 @ 1.45.0

real	0m6,738s
user	0m6,699s
sys	0m0,060s
== Level 14 @ 1.46.0

real	0m11,734s
user	0m11,679s
sys	0m0,064s



== Level 15 @ 1.45.0

real	0m13,908s
user	0m13,833s
sys	0m0,103s
== Level 15 @ 1.46.0

real	0m23,823s
user	0m23,744s
sys	0m0,080s

EDIT: The example provided by @nicholasbishop can be simplified further:

use actix_web::{web, HttpResponse, Responder};
use bb8_postgres::PostgresConnectionManager;
use tokio_postgres::NoTls;


type Pool = bb8::Pool<PostgresConnectionManager<NoTls>>;

async fn handle_req_1(pool: &Pool) {
    let conn = pool.get().await.unwrap();
    conn.query_one("", &[]).await.unwrap();
}


async fn handle_req_final(pool: web::Data<Pool>) -> impl Responder {
    handle_req_1(pool.get_ref()).await;
    HttpResponse::Ok().finish()
}

pub fn app_config() {
    let _ = web::post().to(handle_req_final);
}

With dependencies pre-built, this takes about 0.5s with rustc 1.45.0 and 4.5s with rustc 1.46.0.

@LeSeulArtichaut
Copy link
Contributor

I think @kellerkindt's example above should be good enough to do some bisection, but of course it would be great if we could minimize this further.

@rustbot ping cleanup

@rustbot
Copy link
Collaborator

rustbot commented Aug 28, 2020

Hey Cleanup Crew ICE-breakers! This bug has been identified as a good
"Cleanup ICE-breaking candidate". In case it's useful, here are some
instructions for tackling these sorts of bugs. Maybe take a look?
Thanks! <3

cc @AminArria @camelid @chrissimpkins @contrun @DutchGhost @elshize @ethanboxx @h-michael @HallerPatrick @hdhoang @hellow554 @imtsuki @kanru @KarlK90 @LeSeulArtichaut @MAdrianMattocks @matheus-consoli @mental32 @nmccarty @Noah-Kennedy @pard68 @PeytonT @pierreN @Redblueflame @RobbieClarken @RobertoSnap @robjtede @SarthakSingh31 @senden9 @shekohex @sinato @spastorino @turboladen @woshilapin @yerke

@rustbot rustbot added the ICEBreaker-Cleanup-Crew Helping to "clean up" bugs with minimal examples and bisections label Aug 28, 2020
@Nicholas-Baron

This comment has been minimized.

@algesten
Copy link
Contributor

I think I have a related error. My lib compiled fine under 1.45, but cargo build (and test) breaks under 1.46.

error: reached the type-length limit while instantiating `<std::boxed::Box<std::future::fr..., ()}]>>, ()}]>, ()}]>>>>>::into`
   --> /Users/martin/.rustup/toolchains/stable-x86_64-apple-darwin/lib/rustlib/src/rust/src/libcore/convert/mod.rs:559:5
    |
559 | /     fn into(self) -> U {
560 | |         U::from(self)
561 | |     }
    | |_____^
    |
    = note: consider adding a `#![type_length_limit="1527629"]` attribute to your crate

The code is here, master branch is failing

@kellerkindt
Copy link
Contributor

Yeah, this might be related to #54540. (#54540 (comment))

@kellerkindt
Copy link
Contributor

kellerkindt commented Aug 29, 2020

Did my own bisection (4 times). Each time it identified the regression in nightly-2020-08-14.

One time (probably a timing error/blurp?) the result was:

searched nightlies: from nightly-2020-05-03 to nightly-2020-08-27
regressed nightly: nightly-2020-08-14
searched commits: from 576d27c to 81dc88f
regressed commit: a0c290f

bisected with cargo-bisect-rustc v0.5.2

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

cargo bisect-rustc --test-dir=. --start 2020-05-03 --end 2020-08-27 

Three times the result was (the same as #54540 (comment)) :

searched nightlies: from nightly-2020-05-03 to nightly-2020-08-27
regressed nightly: nightly-2020-08-14
searched commits: from 576d27c to 81dc88f
regressed commit: 0a49057

bisected with cargo-bisect-rustc v0.5.2

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

cargo bisect-rustc --test-dir=. --start 2020-05-03 --end 2020-08-27 
bash script

You may need to tweak this, depending on your local machine.

#!/bin/bash
set -e
rustc --version >> result.txt
echo "Test 1" >> result.txt
time timeout 7 rustc --edition 2018 src/main.rs
echo "Test 2" >> result.txt
time timeout 7 rustc --edition 2018 src/main.rs
echo "Test 3" >> result.txt
time timeout 7 rustc --edition 2018 src/main.rs
rust code
#![recursion_limit="2048"]
#![type_length_limit="112457564"]


pub async fn h0(v: &String, x: &u64) { println!("{} {}", v, x) }
pub async fn h1(v: &String, x: &u64) { h0(v, x).await }
pub async fn h2(v: &String, x: &u64) { h1(v, x).await }
pub async fn h3(v: &String, x: &u64) { h2(v, x).await }
pub async fn h4(v: &String, x: &u64) { h3(v, x).await }
pub async fn h5(v: &String, x: &u64) { h4(v, x).await }
pub async fn h6(v: &String, x: &u64) { h5(v, x).await }
pub async fn h7(v: &String, x: &u64) { h6(v, x).await }
pub async fn h8(v: &String, x: &u64) { h7(v, x).await }
pub async fn h9(v: &String, x: &u64) { h8(v, x).await }

pub async fn h10(v: &String, x: &u64) { h9(v, x).await }
pub async fn h11(v: &String, x: &u64) { h10(v, x).await }
pub async fn h12(v: &String, x: &u64) { h11(v, x).await }
pub async fn h13(v: &String, x: &u64) { h12(v, x).await }
pub async fn h14(v: &String, x: &u64) { h13(v, x).await }
pub async fn h15(v: &String, x: &u64) { h14(v, x).await }
pub async fn h16(v: &String, x: &u64) { h15(v, x).await }
pub async fn h17(v: &String, x: &u64) { h16(v, x).await }
pub async fn h18(v: &String, x: &u64) { h17(v, x).await }
pub async fn h19(v: &String, x: &u64) { h18(v, x).await }


macro_rules! async_recursive {
    (29, $inner:expr) => { async { async_recursive!(28, $inner) }.await };
    (28, $inner:expr) => { async { async_recursive!(27, $inner) }.await };
    (27, $inner:expr) => { async { async_recursive!(26, $inner) }.await };
    (26, $inner:expr) => { async { async_recursive!(25, $inner) }.await };
    (25, $inner:expr) => { async { async_recursive!(24, $inner) }.await };
    (24, $inner:expr) => { async { async_recursive!(23, $inner) }.await };
    (23, $inner:expr) => { async { async_recursive!(22, $inner) }.await };
    (22, $inner:expr) => { async { async_recursive!(21, $inner) }.await };
    (21, $inner:expr) => { async { async_recursive!(20, $inner) }.await };
    (20, $inner:expr) => { async { async_recursive!(19, $inner) }.await };

    (19, $inner:expr) => { async { async_recursive!(18, $inner) }.await };
    (18, $inner:expr) => { async { async_recursive!(17, $inner) }.await };
    (17, $inner:expr) => { async { async_recursive!(16, $inner) }.await };
    (16, $inner:expr) => { async { async_recursive!(15, $inner) }.await };
    (15, $inner:expr) => { async { async_recursive!(14, $inner) }.await };
    (14, $inner:expr) => { async { async_recursive!(13, $inner) }.await };
    (13, $inner:expr) => { async { async_recursive!(12, $inner) }.await };
    (12, $inner:expr) => { async { async_recursive!(11, $inner) }.await };
    (11, $inner:expr) => { async { async_recursive!(10, $inner) }.await };
    (10, $inner:expr) => { async { async_recursive!(9, $inner) }.await };

    (9, $inner:expr) => { async { async_recursive!(8, $inner) }.await };
    (8, $inner:expr) => { async { async_recursive!(7, $inner) }.await };
    (7, $inner:expr) => { async { async_recursive!(6, $inner) }.await };
    (6, $inner:expr) => { async { async_recursive!(5, $inner) }.await };
    (5, $inner:expr) => { async { async_recursive!(4, $inner) }.await };
    (4, $inner:expr) => { async { async_recursive!(3, $inner) }.await };
    (3, $inner:expr) => { async { async_recursive!(2, $inner) }.await };
    (2, $inner:expr) => { async { async_recursive!(1, $inner) }.await };
    (1, $inner:expr) => { async { async_recursive!(0, $inner) }.await };
    (0, $inner:expr) => { async { h19(&String::from("owo"), &0).await; $inner }.await };
}

async fn f() {
    async_recursive!(12, println!("hello"));
    async_recursive!(12, println!("hello"));
    async_recursive!(12, println!("hello"));
}

fn main() {
    let _ = f();
}

EDIT: I also ran the bisection on the original example of @nicholasbishop (which either compiles in finite time with 1.45.x - ~22s for me - or takes forever with 1.46.0), with the same result:

searched nightlies: from nightly-2020-05-03 to nightly-2020-08-27
regressed nightly: nightly-2020-08-14
searched commits: from 576d27c to 81dc88f
regressed commit: 0a49057

bisected with cargo-bisect-rustc v0.5.2

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

cargo bisect-rustc --test-dir=. --start 2020-05-03 --end 2020-08-27 
bash script

You may need to tweak this, depending on your local machine.

#!/bin/bash
set -e
cargo clean
time timeout 35 cargo build

@algesten
Copy link
Contributor

I bisected here algesten/hreq#11

It pointed to #0a49057


Regression in 0a49057


searched nightlies: from nightly-2020-08-12 to nightly-2020-08-15
regressed nightly: nightly-2020-08-14
searched commits: from 576d27c to 81dc88f
regressed commit: 0a49057

bisected with cargo-bisect-rustc v0.5.2

Host triple: x86_64-apple-darwin
Reproduce with:

cargo bisect-rustc --start=2020-08-12 --end=2020-08-15 

@jyn514
Copy link
Member

jyn514 commented Aug 29, 2020

cc @lcnr, this regressed in #75443

@Davester47
Copy link

Davester47 commented Nov 8, 2020

@Adam-Reeves I just tested beta and it works! Nightly however still hangs, and I think that the fix missed the latest nightly. It will probably work tomorrow. Thanks everyone for helping to get this fixed.

Update: my project now builds with nightly.

@bstrie
Copy link
Contributor

bstrie commented Nov 20, 2020

Did anyone ever manage to come up with a minimal, self-contained reproduction for this?

@jyn514
Copy link
Member

jyn514 commented Nov 20, 2020

I think #75992 (comment) is the smallest anyone got it.

@bstrie
Copy link
Contributor

bstrie commented Nov 20, 2020

Good to know, although I wonder if it's premature to close this issue if we don't still have a self-contained repro. Shall we reopen?

@jyn514 jyn514 added E-needs-test Call for participation: An issue has been fixed and does not reproduce, but no test has been added. and removed P-critical Critical priority labels Nov 20, 2020
@jyn514 jyn514 reopened this Nov 20, 2020
@jyn514 jyn514 removed the regression-from-stable-to-stable Performance or correctness regression from one stable version to another. label Nov 20, 2020
@nikomatsakis
Copy link
Contributor

I'd be inclined to close it, I doubt we'll ever follow-up -- if it comes up again, we can try to minimize then.

@marieell
Copy link

I have a similar issue (exponential compile time increase with async and impl trait return values) with 1.50.0 and nightly from 2021-03-05, but my repro is 161 lines and two dependencies. Should I open a new issue or post it here?

@ojeda
Copy link
Contributor

ojeda commented Mar 10, 2021

I'd post it here, it can't hurt and if it is a different issue, then a new one can be posted later on.

@marieell
Copy link

marieell commented Mar 10, 2021

Thanks for your answer :) Since the issue here is fixed it has to be a different one, doesn't it?

@ojeda
Copy link
Contributor

ojeda commented Mar 10, 2021

It could have regressed (since we didn't get a proper repro and there was no regression test added, from a quick read of the thread and the link PR). But yeah, feel free to post a new one and link to this one, both ways are fine. :)

@marieell
Copy link

marieell commented Mar 10, 2021

Ok here it is, it's not great, probably not minimal and uses my crate and futures. I couldn't easily simplify anything, though, especially no types. I get ~2s with async_recursive!(7, ...) and ~14s with async_recursive!(8, ...).

Code
use futures_util::stream::{Stream, StreamExt};
use std::pin::Pin;

trait Thing<V> {
    type Error: Clone;
    fn get(&self) -> Pin<Box<dyn Stream<Item = Result<V, Self::Error>>>>;
}

impl<V: Clone + 'static, E: 'static, S: 'static> Thing<V> for S
where
    S: Stream<Item = Result<V, E>>,
    E: Clone,
{
    type Error = E;
    fn get(&self) -> Pin<Box<dyn Stream<Item = Result<V, Self::Error>>>> {
        unimplemented!()
    }
}

struct Wrapper<'ws, I> {
    inner: I,
    ws: &'ws str,
}

impl<V, I> Thing<V> for Wrapper<'_, I>
where
    I: Thing<V>,
{
    type Error = I::Error;
    fn get(&self) -> Pin<Box<dyn Stream<Item = Result<V, Self::Error>>>> {
        unimplemented!()
    }
}

fn wrap<'ws, V>(v: V) -> Wrapper<'ws, impl Thing<String, Error = V::Error>>
where
    V: Thing<String>,
    V::Error: 'static,
{
    Wrapper { inner: v.get().then(|_| async { unimplemented!() }), ws: "" }
}

macro_rules! async_recursive {
    (15, $inner:expr) => { wrap(async_recursive!(14, $inner)) };
    (14, $inner:expr) => { wrap(async_recursive!(13, $inner)) };
    (13, $inner:expr) => { wrap(async_recursive!(12, $inner)) };
    (12, $inner:expr) => { wrap(async_recursive!(11, $inner)) };
    (11, $inner:expr) => { wrap(async_recursive!(10, $inner)) };
    (10, $inner:expr) => { wrap(async_recursive!(9, $inner)) };
    (9, $inner:expr) => { wrap(async_recursive!(8, $inner)) };
    (8, $inner:expr) => { wrap(async_recursive!(7, $inner)) };
    (7, $inner:expr) => { wrap(async_recursive!(6, $inner)) };
    (6, $inner:expr) => { wrap(async_recursive!(5, $inner)) };
    (5, $inner:expr) => { wrap(async_recursive!(4, $inner)) };
    (4, $inner:expr) => { wrap(async_recursive!(3, $inner)) };
    (3, $inner:expr) => { wrap(async_recursive!(2, $inner)) };
    (2, $inner:expr) => { wrap(async_recursive!(1, $inner)) };
    (1, $inner:expr) => { wrap(async_recursive!(0, $inner)) };
    (0, $inner:expr) => { wrap($inner) };
}

async fn convert<T>(_: T) -> String {
    unimplemented!()
}

pub async fn run(input: impl Stream<Item=Result<String, String>> + 'static) {
    convert(async_recursive!(7, input)).await;
}

I just tried out the code from #75992 (comment) and compilation time is exponential with 1.50.0 – each additional depth level doubles it.

Edit: I got rid of the shared_stream dependency.

@blazzy
Copy link

blazzy commented Mar 11, 2021

Here is my smallish example from attempting to narrow down the source of my horrendously slow compile times: https://github.com/blazzy/slow-rust-async/blob/master/src/lib.rs

It definitely seems to get exponentially worse the deeper the levels of async nesting. Seconds become minutes and minutes become 10s of minutes.

If this is the same issue, should it maybe go back to being p-critical? :-)

macro_rules! compose_middleware_inner {
  ( $route:ident, $first:ident, $second:ident, $($tail:ident), +) => {
    $first(|| async {
        compose_middleware_inner!($route, $second, $($tail),+)
    }).await
  };
  ( $route: ident, $first:ident, $second:ident ) => {
    $first(|| async move { $second($route).await }).await
  };
}

macro_rules! compose_middleware {
    ( $name:ident, $($tail:ident), +) => {
        pub async fn $name<N, Fut>(route: N)
        where
            N: FnOnce() -> Fut,
            Fut: std::future::Future<Output = ()>,
        {
            compose_middleware_inner!(route, $($tail),+)
        }
    }
}

async fn log<N, Fut>(next: N)
where
    N: FnOnce() -> Fut,
    Fut: std::future::Future<Output = ()>,
{
    next().await;
}

compose_middleware!(my_middleware, log, log, log, log, log, log, log, log, log, log, log, log);

@blazzy
Copy link

blazzy commented Mar 11, 2021

I think this might actually be a somewhat different issue. Going back as far as 1.39, I couldn't find a version where this code scales well with depth. 😕

@nellshamrell
Copy link
Contributor

Given discussion above, closing and tracking future issues in #83031.

@marieell
Copy link

You didn't actually close this issue :) Also, my case doesn't compile faster in release mode.

@nellshamrell
Copy link
Contributor

That is a good point - this may still be a separate issue, leaving open for now. (Sorry for the double post and then not closing, GitHub is throwing a fit on me)

@rust-lang rust-lang deleted a comment from nellshamrell Mar 12, 2021
@marieell
Copy link

I simplified my example (#75992 (comment)) and tried it with nightly-2019-11-07, which has the same compile time behavior, so bisecting is probably useless.

@marieell
Copy link

marieell commented Mar 13, 2021

-Zself-profile (thanks to @blazzy for the tip) says that check_mod_item_types is the problem (in my example).

head of profile
+--------------------------------------------------+-----------+-----------------+----------+------------+-----------------------+
| Item                                             | Self time | % of total time | Time     | Item count | Incremental load time |
+--------------------------------------------------+-----------+-----------------+----------+------------+-----------------------+
| check_mod_item_types                             | 1.67s     | 90.850          | 1.69s    | 1          | 0.00ns                |
+--------------------------------------------------+-----------+-----------------+----------+------------+-----------------------+
| normalize_projection_ty                          | 71.78ms   | 3.899           | 72.25ms  | 17         | 0.00ns                |
+--------------------------------------------------+-----------+-----------------+----------+------------+-----------------------+
| metadata_register_crate                          | 22.48ms   | 1.221           | 39.05ms  | 25         | 0.00ns                |
+--------------------------------------------------+-----------+-----------------+----------+------------+-----------------------+
| expand_crate                                     | 11.13ms   | 0.605           | 39.22ms  | 1          | 0.00ns                |

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-async-await Area: Async & Await AsyncAwait-Triaged Async-await issues that have been triaged during a working group meeting. C-bug Category: This is a bug. E-needs-mcve Call for participation: This issue has a repro, but needs a Minimal Complete and Verifiable Example E-needs-test Call for participation: An issue has been fixed and does not reproduce, but no test has been added. I-compilemem Issue: Problems and improvements with respect to memory usage during compilation. I-compiletime Issue: Problems and improvements with respect to compile times. I-hang Issue: The compiler never terminates, due to infinite loops, deadlock, livelock, etc. ICEBreaker-Cleanup-Crew Helping to "clean up" bugs with minimal examples and bisections T-compiler Relevant to the compiler team, which will review and decide on the PR/issue.
Projects
Archived in project