Add wasm-opt log-execution support

[vshymanskyy]

Motivation

wasm-opt --log-execution allows to instrument an existing wasm file and trace execution.
It would be great if wasmer could support running such files out of the box.

A use case for this would be:
Run an instrumented wasm file in multiple engines, compare the execution flow (with diff, etc).

Proposed solution

The instrumented file imports log_execution function:

(type $t2 (func (param i32)))
(import "env" "log_execution" (func $env.log_execution (type $t2)))

(the number argument is just an id of a tracepoint).

This feature should be very simple to implement.
Whenever wasm module calls env:log_execution, the runtime should print the tracepoint id to a text log file (in current directory, i.e. ./wasmer_trace.log).

Additional context

There are also other tracing instrumentation options in wasm-opt, like--instrument-memory, --instrument-locals, which require implementing a few more imported functions, but would be really awesome to have them working out of the box. They should output to the same trace file.

[vshymanskyy]

I have created such tracer, based on Wasmer.js: https://github.com/wasm3/wasm-trace
It works, but it's not optimal.. Definitely would like to see this feature available out of the box in Wasmer.
@syrusakbary what do you think?

[syrusakbary]

That's great @vshymanskyy!

I think it would be good to have it in Wasmer.
We will need to put it behind a flag in the CLI (such as wasmer --trace-execution=trace.log ...) and then plug the env function into the imports https://github.com/wasmerio/wasmer/blob/master/src/bin/wasmer.rs.

I think creating a function that receives an import object, and returns the same import object vitaminized with the extra import would be a way to have it working for all different integrations (WASI, Emscripten and standalone).

Any contribution on that front will be welcome (we can give guidance if needed!)

[vshymanskyy]

I have uploaded some example input/output files here:
https://github.com/wasm3/wasm-trace/tree/master/test
While executing hello.instrumented.wasm, the engine should produce a simple CSV file (hello.instrumented.csv for reference).
Then wasm-trace utility takes care to generate the structured output file: hello.instrumented.log.

[vshymanskyy]

@syrusakbary I have implemented support for Wasmer-js in the wasm-trace tool.
The instrumentation handling part is trivial in this case: https://github.com/wasm3/wasm-trace/blob/a622a9514b17043efefd53ca874bd7c72384b5ad/wasm-trace.js#L284-L321
However I probably won't be able to dive into Rust development anytime soon.

[vshymanskyy]

Implementation for Wasm3 was also quite simple:
https://github.com/wasm3/wasm3/blob/master/source/m3_api_tracer.c

Here's an example of engine decoupling:

$ wasm3 ./test/hello.instrumented.wasm
Hello WebAssembly!
$ wasm-trace --process=wasm3_trace.csv -o wasm3_trace.log ./test/hello.instrumented.wasm
[tracer] Processing...
$ cat wasm3_trace.log | head -n 10
     2 | enter _start {
     0 |   set i32: 0 68256
    41 |   enter __wasilibc_init_preopen {
     4 |     enter malloc {
    32 |       get i32: 0 16
    21 |       enter dlmalloc {
    33 |         set i32: 1 68240
    34 |         get i32: 0 16
     5 |         load i32: 0+1056 0
    35 |         set i32: 2 0

@syrusakbary However, I expect some imported functions will change as the instrumentation gets more mature. So no rush, it may take time until it stabilizes.

[MarkMcCaskey]

@vshymanskyy I'm looking into this now and ran into an issue: my copy of wasm-opt doesn't seem to be outputting enter, exit and loop calls 🤔.

wasm-opt --log-execution --instrument-memory --instrument-locals in.wasm -o out.wasm is the command I'm running. Am I missing a flag? I couldn't find a relevant looking flag in the help output

[vshymanskyy]

Correct. This is performed by a custom pass I'm working on. The pre-instrumented file (`./test/hello.instrumented.wasm`) contains this transformation. However the API for this pass can change. I'd like to add tracing of imported function calls and arguments/return values.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[Hywan]

Still relevant.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale]

Feel free to reopen the issue if it has been closed by mistake.