tracing::instrument: "Reached the type-length limit while instantiating ..."

[akshayknarayan]

Bug Report

Version

├── tracing v0.1.10
│   ├── tracing-attributes v0.1.7
│   └── tracing-core v0.1.10
├── tracing-attributes v0.1.7 (*)
└── tracing-futures v0.2.3
    └── tracing v0.1.10 (*)

Platform

Linux 4.19.0

Crates

tracing-attributes v 0.1.7

Description

Best-effort minimal example:

#[tokio::main]
async fn main() {
    foo_4().await.unwrap();
}

#[tracing::instrument(level = "debug")]
async fn foo() -> usize {
    0
}

#[tracing::instrument(level = "debug")]
async fn foo_1() -> Result<(), ()> {
    foo().await;
    Ok(())
}

#[tracing::instrument(level = "debug")]
async fn foo_2() -> Result<(), ()> {
    return foo_1().await;
}

#[tracing::instrument(level = "debug")]
async fn foo_3() -> Result<(), ()> {
    return foo_2().await;
}

#[tracing::instrument(level = "debug")]
async fn foo_4() -> Result<(), ()> {
    return foo_3().await;
}

This causes:

error: reached the type-length limit while instantiating `std::pin::Pin::<&mut std::future...}[1]::poll[0]::{{closure}}[0])]>`
    |
    = note: consider adding a `#![type_length_limit="1439423"]` attribute to your crate

tracing-attributes + tracing-futures seems to be inflating the type-length significantly?

[akshayknarayan]

Perhaps related to rust-lang/rust#58952

[hawkw]

Perhaps related to rust-lang/rust#58952

Hmm, this does seem similar to rust-lang/rust#54540 (the issue that that one is believed to be a duplicate of) at a glance.

I'm not sure if there is anything tracing can do to fix this: the codegen for async fns is essentially adding an async block inside of each generated function, wrapping it in an Instrumented future, and awaiting it, which does introduce additional type complexity — each layer of instrument is adding a wrapper future and two Pins. I don't think there's any other way to get the needed behavior to instrument async functions. However, I'm definitely surprised that causes type lengths to blow up fast enough that you see a compiler failure after only 4 nested instrumented functions...

Can you reproduce this with earlier versions of tracing-attributes?

[akshayknarayan]

Thanks for the explanation :)

Can you reproduce this with earlier versions of tracing-attributes?

Yes, this example reproduces back to tracing-attributes 0.1.1 (on rustc 1.41.1). As a result, I think it's reasonable to conclude that this is indeed due to rust-lang/rust#54540.

[hawkw]

As a temporary workaround, I suspect sticking a Box halfway though the chain of async fn calls will help...

[teor2345]

The fix for rust-lang/rust#75313 increases the size of some types generated by tracing::instrument. The fix is in recent nightlies, and it is also proposed for backport to beta.

After the fix, we saw "reached the type-length limit" with spans that were 4 functions deep. But the test case in this ticket goes 5 functions deep before failure.

For details, see rust-lang/rust#75313 (comment) and ZcashFoundation/zebra#923.

[djc]

In Quinn we similarly observe that rust-lang/rust#75443 has triggered the requirement to set a type-lengh limit in one of our crates for the first time (like zebra, we use tracing in that crate), tracked in quinn-rs/quinn#839.

[Ralith]

Note that, unlike the OP, quinn does not use the proc macros. The relevant code is:

    let results = future::join_all(peers.into_iter().map(|peer| async move {
        let span = info_span!("peer", name = peer.name.as_str());
        let result = run(&peer, keylog).instrument(span).await;
        (peer, result)
    }));

Maybe info_span! is generating something complex?

[hawkw]

Hmm, that's interesting. @Ralith and @djc, what happens if you try with a Git dep on 0454d6b? Can you still reproduce the error?

[djc]

Yup, the error still reproduces.

diff --git a/Cargo.toml b/Cargo.toml
index c1d28011..44d4264b 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -6,3 +6,8 @@ debug = true
 
 [profile.release]
 debug = true
+
+[patch."crates-io"]
+tracing = { git = "https://github.com/tokio-rs/tracing", rev = "0454d6b41204a5cf98094ae1bebf20f6d97cb60b" }
+tracing-subscriber = { git = "https://github.com/tokio-rs/tracing", rev = "0454d6b41204a5cf98094ae1bebf20f6d97cb60b" }
+tracing-futures = { git = "https://github.com/tokio-rs/tracing", rev = "0454d6b41204a5cf98094ae1bebf20f6d97cb60b" }