wasmtime / PR #9217 Use `tracing::Instrument` in generate... · git-wasmtime

Stream: git-wasmtime

Topic: wasmtime / PR #9217 Use `tracing::Instrument` in generate...

Wasmtime GitHub notifications bot (Sep 09 2024 at 21:00):

swlynch99 requested alexcrichton for a review on PR #9217.

Wasmtime GitHub notifications bot (Sep 09 2024 at 21:00):

swlynch99 requested wasmtime-core-reviewers for a review on PR #9217.

Wasmtime GitHub notifications bot (Sep 09 2024 at 21:00):

swlynch99 opened PR #9217 from swlynch99:wit-bindgen-span-fix to bytecodealliance:main:

<!--
Please make sure you include the following information:

If this work has been discussed elsewhere, please include a link to that
conversation. If it was discussed in an issue, just mention "issue #...".
Explain why this change is needed. If the details are in an issue already,
this can be brief.

Our development process is documented in the Wasmtime book:
https://docs.wasmtime.dev/contributing-development-process.html

Please ensure all communication follows the code of conduct:
https://github.com/bytecodealliance/wasmtime/blob/main/CODE_OF_CONDUCT.md
-->

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.

Wasmtime GitHub notifications bot (Sep 09 2024 at 21:57):

swlynch99 updated PR #9217.

Wasmtime GitHub notifications bot (Sep 09 2024 at 22:02):

alexcrichton submitted PR review:

Thanks for this!

Wasmtime GitHub notifications bot (Sep 09 2024 at 22:02):

alexcrichton has enabled auto merge for PR #9217.

Wasmtime GitHub notifications bot (Sep 09 2024 at 22:09):

swlynch99 edited PR #9217:

<!--
Please make sure you include the following information:

If this work has been discussed elsewhere, please include a link to that
conversation. If it was discussed in an issue, just mention "issue #...".
Explain why this change is needed. If the details are in an issue already,
this can be brief.

Our development process is documented in the Wasmtime book:
https://docs.wasmtime.dev/contributing-development-process.html

Please ensure all communication follows the code of conduct:
https://github.com/bytecodealliance/wasmtime/blob/main/CODE_OF_CONDUCT.md
-->

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 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.

Wasmtime GitHub notifications bot (Sep 10 2024 at 00:21):

swlynch99 commented on PR #9217:

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

Wasmtime GitHub notifications bot (Sep 10 2024 at 00:24):

pchickey commented on PR #9217:

Sometimes runners just flake, lets try it again

Wasmtime GitHub notifications bot (Sep 10 2024 at 00:38):

pchickey merged PR #9217.

Last updated: Dec 23 2024 at 12:05 UTC