Skip to content

Use tracing::Instrument in generated bindings to avoid holding spans across await points#9217

Merged
pchickey merged 2 commits intobytecodealliance:mainfrom
swlynch99:wit-bindgen-span-fix
Sep 10, 2024
Merged

Use tracing::Instrument in generated bindings to avoid holding spans across await points#9217
pchickey merged 2 commits intobytecodealliance:mainfrom
swlynch99:wit-bindgen-span-fix

Conversation

@swlynch99
Copy link
Copy Markdown
Contributor

@swlynch99 swlynch99 commented Sep 9, 2024

This PR fixes #9210.

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in add_to_linker_get_host would look like this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is suspended. The end result is that other unrelated tokio tasks running on the same thread in the meantime will be shown as executing within the wit-bindgen import span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, tracing::Instrument takes care of entering the span when the future is polled and exiting it when it is suspended.

I have also manually verified that the codegen for sync functions remains exactly the same.

across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes bytecodealliance#9210
Copy link
Copy Markdown
Member

@alexcrichton alexcrichton left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for this!

@alexcrichton alexcrichton added this pull request to the merge queue Sep 9, 2024
@github-merge-queue github-merge-queue bot removed this pull request from the merge queue due to no response for status checks Sep 10, 2024
@swlynch99
Copy link
Copy Markdown
Contributor Author

The macos wasmtime CI job seems to be stalled when running cargo fetch? I'm not sure what's up with that.

@pchickey pchickey added this pull request to the merge queue Sep 10, 2024
@pchickey
Copy link
Copy Markdown
Contributor

Sometimes runners just flake, lets try it again

Merged via the queue into bytecodealliance:main with commit 2b29e45 Sep 10, 2024
@swlynch99 swlynch99 deleted the wit-bindgen-span-fix branch September 10, 2024 00:47
elliottt pushed a commit to elliottt/wasmtime that referenced this pull request Sep 16, 2024
…s across await points (bytecodealliance#9217)

* Use `tracing::Instrument` in generated bindings to avoid holding spans
across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes bytecodealliance#9210

* Bless expanded macro outputs
alexcrichton pushed a commit that referenced this pull request Sep 16, 2024
* Use `tracing::Instrument` in generated bindings to avoid holding spans across await points (#9217)

* Use `tracing::Instrument` in generated bindings to avoid holding spans
across await points

Previously, if we had a WIT file with a function

async-fn: func();

then the generated code in `add_to_linker_get_host` would look like
this (if tracing is enabled and the function is async)

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

This keeps the tracing span active, even when the resulting future is
suspended. The end result is that other unrelated tokio tasks running on
the same thread in the meantime will be shown as executing within the
`wit-bindgen import` span.

This commit changes the codegen to instead generate

inst.func_wrap_async(
    "async-fn",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        use tracing::Instrument;

        let span = tracing::span!(
            tracing::Level::TRACE,
            "wit-bindgen import",
            module = "test",
            function = "async-fn",
        );
        wasmtime::component::__internal::Box::new(
            async move {
                tracing::event!(tracing::Level::TRACE, "call");
                let host = &mut host_getter(caller.data_mut());
                let r = Host::async_fn(host).await;
                tracing::event!(
                    tracing::Level::TRACE,
                    result = tracing::field::debug(&r),
                    "return"
                );
                Ok(r)
            }
            .instrument(span),
        )
    },
)?;

Here, `tracing::Instrument` takes care of entering the span when the
future is polled and exiting it when it is suspended.

Fixes #9210

* Bless expanded macro outputs

* Update the release notes

---------

Co-authored-by: Sean Lynch <42618346+swlynch99@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Tracing spans in code generated by wasmtime-wit-bindgen are entered incorrectly for async functions

3 participants