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

[nicholasbishop]

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)

[jyn514]

Possible duplicate of #72408?

[kellerkindt]

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

[jyn514]

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

[ojeda]

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

Well, it is a nearly perfect exponential fit!

[kellerkindt]

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]

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