Stream: git-wasmtime

Topic: wasmtime / issue #4059 Timeout during spec interpreter ex...

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:05):

alexcrichton opened issue #4059:

We hit a fuzz bug just now where the spec interpreter is timing out the fuzz test case when wasmtime looks to execute the wasm in under a second, so I'm opening this to track investigation into the spec interpreter to see if there's perhaps some performance wins to gain there.

cc @conrad-watt

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:05):

alexcrichton labeled issue #4059:

We hit a fuzz bug just now where the spec interpreter is timing out the fuzz test case when wasmtime looks to execute the wasm in under a second, so I'm opening this to track investigation into the spec interpreter to see if there's perhaps some performance wins to gain there.

cc @conrad-watt

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:07):

alexcrichton commented on issue #4059:

Ah and for reference locally the spec interpreter is taking ~1 minute. I'm not entirely sure how to profile ocaml but perf is reporting:

<img width="704" alt="Screen Shot 2022-04-20 at 3 06 56 PM" src="https://user-images.githubusercontent.com/64996/164313995-d7c14c0c-c702-4f15-8731-279d5b5ac58d.png">

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:24):

conrad-watt commented on issue #4059:

Ah, interesting. The formal model's implementations of reinterpret and popcnt are particularly inefficient (still a constant factor only), and it looks like this test calls a whole bunch of them. I'll dig into this on my side, but do you see a big difference in the (forked) spec interpreter's runtime locally when providing/not providing the -isa flag?

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:27):

alexcrichton commented on issue #4059:

Ah sorry I'm not super familiar with running the interpreter outside the fuzzer itself, can you clarify what you mean by the -isa flag?

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:33):

conrad-watt commented on issue #4059:

Ah sorry, if it's any trouble, I can look myself later (not at my workstation right now).

When running the spec interpreter from the command line, the invocation normally looks like

./bin-name -i file-name

this runs the reference interpreter (more or less) unchanged from the main repository

if you instead run

./bin-name -isa -i file-name

it runs using my formal model

if it runs much slower with the -isa flag provided, that suggests the culprit is my slow implementation of reinterpret and popcnt.

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:34):

conrad-watt edited a comment on issue #4059:

Ah sorry, if it's any trouble, I can look myself later (not at my workstation right now).

When running the spec interpreter from the command line, the invocation normally looks like

./bin-name -i file-name

this runs the reference interpreter (more or less) unchanged from the main repository

if you instead run

./bin-name -isa -i file-name

it runs using my formal model (this flag is only implemented in my fork)

if it runs much slower with the -isa flag provided, that suggests the culprit is my slow implementation of reinterpret and popcnt.

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:37):

conrad-watt edited a comment on issue #4059:

Ah sorry, if it's any trouble, I can look myself later (not at my workstation right now).

When running the spec interpreter from the command line, the invocation normally looks like

./exe-name -i file-name

this runs the reference interpreter (more or less) unchanged from the main repository

if you instead run

./exe-name -isa -i file-name

it runs using my formal model (this flag is only implemented in my fork)

if it runs much slower with the -isa flag provided, that suggests the culprit is my slow implementation of reinterpret and popcnt.

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:41):

alexcrichton commented on issue #4059:

Ah ok makes sense!

Looks like the default spec interpreter executes this in 0.8s, and the -isa flag runs in 74s

I used this small script to execute the interpreter:

expr="(assert_return (invoke \"\""
for i in `seq 0 19`; do
  expr="$expr (f32.const 0)"
done
expr="$expr) (f32.const 0))"
time ./wasm -i $HOME/code/wasmtime/testcase0.wasm -e "$expr"
time ./wasm -isa -i $HOME/code/wasmtime/testcase0.wasm -e "$expr"

Also to clarify it's not urgent to fix this, just wanted to log this as the fuzz bug came in

view this post on Zulip Wasmtime GitHub notifications bot (Apr 20 2022 at 20:41):

conrad-watt edited a comment on issue #4059:

Ah sorry, if it's any trouble, I can look myself later (not at my workstation right now).

When running the spec interpreter from the command line, the invocation normally looks like

./exe-name -i file-name

this runs the reference interpreter (more or less) unchanged from the main repository

if you instead run

./exe-name -isa -i file-name

it runs using my formal model (this flag is only implemented in my fork)

if it runs much slower with the -isa flag provided, that suggests the culprit is my slow implementation of reinterpret and popcnt.

EDIT: I should clarify that the fuzzer is only set up to run using the formal model path right now

view this post on Zulip Wasmtime GitHub notifications bot (Apr 27 2022 at 00:52):

conrad-watt commented on issue #4059:

Just to flag up - I've identified a fix, but I'm currently dealing with an unrelated deadline, so I'll probably make a PR late next week.

view this post on Zulip Wasmtime GitHub notifications bot (May 09 2022 at 15:58):

conrad-watt commented on issue #4059:

With the fix in https://github.com/bytecodealliance/wasmtime/pull/4113, the Isabelle-based interpreter seems to (thankfully!) outperform the base spec interpreter on this example. As I feared, the culprit was popcnt's performance. As I mention in that PR, there are a few more ops which could currently cause similar timeouts if a fuzz test is heavily weighted towards them, so I'll work on fixing those next.

view this post on Zulip Wasmtime GitHub notifications bot (May 09 2022 at 16:10):

alexcrichton commented on issue #4059:

Sounds good! I'll ping here if we get a concrete test case but otherwise I'm gonna go ahead and close this since the fuzz bug in question is now fixed.

view this post on Zulip Wasmtime GitHub notifications bot (May 09 2022 at 16:10):

alexcrichton closed issue #4059:

We hit a fuzz bug just now where the spec interpreter is timing out the fuzz test case when wasmtime looks to execute the wasm in under a second, so I'm opening this to track investigation into the spec interpreter to see if there's perhaps some performance wins to gain there.

cc @conrad-watt

Last updated: Oct 23 2024 at 20:03 UTC