wasmtime / issue #5628 bug: running with `--vtune` causes... · git-wasmtime

Stream: git-wasmtime

Topic: wasmtime / issue #5628 bug: running with `--vtune` causes...

Wasmtime GitHub notifications bot (Jan 24 2023 at 23:37):

Test Case

(module)

Steps to Reproduce

wasmtime --vtune /tmp/empty.wat

Expected Results

Adding the --vtune flag, which enables VTune profiling, should succeed regardless of the environment.

Actual Results

A snippet of the backtrace:

thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: error when notifying event', crates/jit/src/profiling/vtune.rs:60:14
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', crates/jit/src/profiling/vtune.rs:47:27
...
 17:     0x564e6a13571c - <wasmtime_jit::profiling::vtune::VTuneAgent as core::ops::drop::Drop>::drop::ha421249d00e9da25
                               at /.../wasmtime/src/crates/jit/src/profiling/vtune.rs:47:9
  18:     0x564e6935d677 - core::ptr::drop_in_place<wasmtime_jit::profiling::vtune::VTuneAgent>::h4021027fefeb76a5
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  19:     0x564e6935f22d - core::ptr::drop_in_place<alloc::boxed::Box<dyn wasmtime_jit::profiling::ProfilingAgent>>::h3e6586f99c95bc40
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  20:     0x564e6935c24c - core::ptr::drop_in_place<wasmtime::engine::EngineInner>::hb7a0d51da9c6653e
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  21:     0x564e693b2b64 - alloc::sync::Arc<T>::drop_slow::h6c0d38bb7bee604c
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1114:18
  22:     0x564e6935f9fb - <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop::haeb7e9ee9f329b2a
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1711:13
  23:     0x564e6935e00b - core::ptr::drop_in_place<alloc::sync::Arc<wasmtime::engine::EngineInner>>::h4fab3897c40d1cc6
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  24:     0x564e6935bb9b - core::ptr::drop_in_place<wasmtime::engine::Engine>::h804e987e96a87bb3
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  25:     0x564e68f55ce4 - wasmtime_cli::commands::run::RunCommand::execute::h6e097e3761430deb
                               at /.../wasmtime/src/src/commands/run.rs:230:5
  26:     0x564e68dcb405 - wasmtime::Wasmtime::execute::hc576e9eb67754303
                               at /.../wasmtime/src/src/bin/wasmtime.rs:52:29

Versions and Environment

Wasmtime version or commit: main

Operating system: Fedora

Architecture: x86_64

Extra Info

I thought that perhaps the issue was that Wasmtime expected to be run by VTune. When I try the following, things seem to almost work:

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune /tmp/empty.wat

I do see a worrying line in the output, though: vtune: Error: Cannot load data file /tmp/vtune-results/data.0/40123-40133.0.trace' (Data file is corrupted).` But I can replicate the original bug when I use a more complex WAT file:

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune ~/Code/wasmtime/tests/all/cli_tests/simple.wat

Wasmtime GitHub notifications bot (Jan 24 2023 at 23:37):

abrown labeled issue #5628:

Test Case

(module)

Steps to Reproduce

wasmtime --vtune /tmp/empty.wat

Expected Results

Adding the --vtune flag, which enables VTune profiling, should succeed regardless of the environment.

Actual Results

A snippet of the backtrace:

thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: error when notifying event', crates/jit/src/profiling/vtune.rs:60:14
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', crates/jit/src/profiling/vtune.rs:47:27
...
 17:     0x564e6a13571c - <wasmtime_jit::profiling::vtune::VTuneAgent as core::ops::drop::Drop>::drop::ha421249d00e9da25
                               at /.../wasmtime/src/crates/jit/src/profiling/vtune.rs:47:9
  18:     0x564e6935d677 - core::ptr::drop_in_place<wasmtime_jit::profiling::vtune::VTuneAgent>::h4021027fefeb76a5
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  19:     0x564e6935f22d - core::ptr::drop_in_place<alloc::boxed::Box<dyn wasmtime_jit::profiling::ProfilingAgent>>::h3e6586f99c95bc40
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  20:     0x564e6935c24c - core::ptr::drop_in_place<wasmtime::engine::EngineInner>::hb7a0d51da9c6653e
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  21:     0x564e693b2b64 - alloc::sync::Arc<T>::drop_slow::h6c0d38bb7bee604c
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1114:18
  22:     0x564e6935f9fb - <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop::haeb7e9ee9f329b2a
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1711:13
  23:     0x564e6935e00b - core::ptr::drop_in_place<alloc::sync::Arc<wasmtime::engine::EngineInner>>::h4fab3897c40d1cc6
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  24:     0x564e6935bb9b - core::ptr::drop_in_place<wasmtime::engine::Engine>::h804e987e96a87bb3
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  25:     0x564e68f55ce4 - wasmtime_cli::commands::run::RunCommand::execute::h6e097e3761430deb
                               at /.../wasmtime/src/src/commands/run.rs:230:5
  26:     0x564e68dcb405 - wasmtime::Wasmtime::execute::hc576e9eb67754303
                               at /.../wasmtime/src/src/bin/wasmtime.rs:52:29

Versions and Environment

Wasmtime version or commit: main

Operating system: Fedora

Architecture: x86_64

Extra Info

I thought that perhaps the issue was that Wasmtime expected to be run by VTune. When I try the following, things seem to almost work:

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune /tmp/empty.wat

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune ~/Code/wasmtime/tests/all/cli_tests/simple.wat

Wasmtime GitHub notifications bot (Jan 24 2023 at 23:38):

abrown edited issue #5628:

Test Case

(module)

Steps to Reproduce

wasmtime --vtune /tmp/empty.wat

Expected Results

Adding the --vtune flag, which enables VTune profiling, should succeed regardless of the environment.

Actual Results

A snippet of the backtrace:

thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: error when notifying event', crates/jit/src/profiling/vtune.rs:60:14
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', crates/jit/src/profiling/vtune.rs:47:27
...
 17:     0x564e6a13571c - <wasmtime_jit::profiling::vtune::VTuneAgent as core::ops::drop::Drop>::drop::ha421249d00e9da25
                               at /.../wasmtime/src/crates/jit/src/profiling/vtune.rs:47:9
  18:     0x564e6935d677 - core::ptr::drop_in_place<wasmtime_jit::profiling::vtune::VTuneAgent>::h4021027fefeb76a5
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  19:     0x564e6935f22d - core::ptr::drop_in_place<alloc::boxed::Box<dyn wasmtime_jit::profiling::ProfilingAgent>>::h3e6586f99c95bc40
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  20:     0x564e6935c24c - core::ptr::drop_in_place<wasmtime::engine::EngineInner>::hb7a0d51da9c6653e
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  21:     0x564e693b2b64 - alloc::sync::Arc<T>::drop_slow::h6c0d38bb7bee604c
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1114:18
  22:     0x564e6935f9fb - <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop::haeb7e9ee9f329b2a
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1711:13
  23:     0x564e6935e00b - core::ptr::drop_in_place<alloc::sync::Arc<wasmtime::engine::EngineInner>>::h4fab3897c40d1cc6
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  24:     0x564e6935bb9b - core::ptr::drop_in_place<wasmtime::engine::Engine>::h804e987e96a87bb3
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  25:     0x564e68f55ce4 - wasmtime_cli::commands::run::RunCommand::execute::h6e097e3761430deb
                               at /.../wasmtime/src/src/commands/run.rs:230:5
  26:     0x564e68dcb405 - wasmtime::Wasmtime::execute::hc576e9eb67754303
                               at /.../wasmtime/src/src/bin/wasmtime.rs:52:29

Versions and Environment

Wasmtime version or commit: main

Operating system: Fedora

Architecture: x86_64

Extra Info

I thought that perhaps the issue was that Wasmtime expected to be run by VTune. When I try the following, things seem to almost work:

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune /tmp/empty.wat

I do see a worrying line in the output, though: "vtune: Error: Cannot load data file `/tmp/vtune-results/data.0/40123-40133.0.trace' (Data file is corrupted)." But I can replicate the original bug when I use a more complex WAT file:

rm -rf /tmp/vtune-results
vtune -collect hotspots -result-dir /tmp/vtune-results target/debug/wasmtime --vtune ~/Code/wasmtime/tests/all/cli_tests/simple.wat

Wasmtime GitHub notifications bot (Jan 24 2023 at 23:38):

abrown commented on issue #5628:

cc: @jlb6740, @bnjbvr

Wasmtime GitHub notifications bot (Jan 25 2023 at 12:17):

bnjbvr commented on issue #5628:

Thanks! I've just ran into that in our embedding too; will investigate quickly to find if there's anything obvious there.

Wasmtime GitHub notifications bot (Jan 25 2023 at 15:06):

bnjbvr commented on issue #5628:

@abrown so at the end of this short investigation:

I couldn't run under vtune, as running vtune on my OS fails with a cryptic library loading error (probably the package is borked).

From scanning the issue in our embedding, it seems that running outside vtune fails when notify_event is called for new methods. That being said, I've just noticed the documentation of this method for ...METHOD_LOAD_FINISHED says that the return value is undefined for this particular event type, while the high-level ittapi crate will check it's 1 to decide it's been successful, independently of the event. I've opened https://github.com/intel/ittapi/pull/82 to fix that.

I can see that the shutdown results in a error, when trying with your test case; that being said, it only output to log, in my case, and doesn't crash. So I'm wondering if we're running into different issues, or if some of them are OS-specific ("I'm running ArchLinux, btw").

Wasmtime GitHub notifications bot (Jan 25 2023 at 22:26):

abrown commented on issue #5628:

Made some comments over in https://github.com/intel/ittapi/pull/82.

Last updated: Oct 23 2024 at 20:03 UTC