Stream: git-wasmtime

Topic: wasmtime / PR #7220 threads: log every `wait` and `notify`

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:46):

abrown opened PR #7220 from abrown:log-wait-notify to bytecodealliance:main:

When troubleshooting deadlocks in WebAssembly modules, it is important to understand which wait instructions are still pending a notify. It would be nice to have some kind of --warn-deadlock-after=1s flag available that would poll the parking lot for waits hanging past the time limit, but I realized the real value would be to tie the wait instruction (through CLIF) to the original source code, if debug information were available. This did not seem to be entirely feasible, since CLIF loses the original Wasm source context (is this true?) and I was not confident that we would be able to use addr2line to map from Wasm instructions to source (e.g., see @cfallin's
issue).

Instead, this change simply logs each valid wait and notify execution, leaving it to the user to figure out which one is hanging (should not be too difficult) and how to map this back to their source code (more difficult).

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

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:47):

abrown edited PR #7220:

When troubleshooting deadlocks in WebAssembly modules, it is important to understand which wait instructions are still pending a notify. It would be nice to have some kind of --warn-deadlock-after=1s flag available that would poll the parking lot for waits hanging past the time limit, but I realized the real value would be to tie the wait instruction (through CLIF) to the original source code, if debug information were available. This did not seem to be entirely feasible, since CLIF loses the original Wasm source context (is this true?) and I was not confident that we would be able to use addr2line to map from Wasm instructions to source (e.g., see @cfallin's issue).

Instead, this change simply logs each valid wait and notify execution, leaving it to the user to figure out which one is hanging (should not be too difficult) and how to map this back to their source code (more difficult).

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

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:47):

abrown has marked PR #7220 as ready for review.

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:47):

abrown requested wasmtime-core-reviewers for a review on PR #7220.

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:47):

abrown requested pchickey for a review on PR #7220.

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:58):

pchickey submitted PR review:

lgtm, modulo a style change across all of these traces

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:58):

pchickey submitted PR review:

lgtm, modulo a style change across all of these traces

Wasmtime GitHub notifications bot (Oct 11 2023 at 18:58):

pchickey created PR review comment:

instead of using the format string, use log::trace!("memory.atomic.notify", addr=addr_index, count=count); to provide structured values.

Wasmtime GitHub notifications bot (Oct 11 2023 at 21:59):

abrown submitted PR review.

Wasmtime GitHub notifications bot (Oct 11 2023 at 21:59):

abrown created PR review comment:

I tried that but it complains: I think to use the key-value syntax we need to set target: ..., up front and still provide a string at the end (see log::log!)?

Wasmtime GitHub notifications bot (Oct 11 2023 at 22:28):

pchickey submitted PR review.

Wasmtime GitHub notifications bot (Oct 11 2023 at 22:28):

pchickey created PR review comment:

oh, my bad. I just realized this is log and the key value syntax only works with the tracing crate, and I forgot we use log in wasmtime-runtime in order to keep the dependencies as small as possible, but tracing in wasmtime-wit-bindgen, wasi, etc.

So, your PR is good to go as is. I don't think we need should using log vs tracing down in the runtime now, unless someone really wants to.

Wasmtime GitHub notifications bot (Oct 11 2023 at 22:28):

pchickey submitted PR review.

Wasmtime GitHub notifications bot (Oct 11 2023 at 23:24):

abrown merged PR #7220.

Last updated: Oct 23 2024 at 20:03 UTC