Performance Issue in the fd_write Implementation

[hungryzzz]

Summary

Hi, I run the following case in different Wasm runtimes(after being compiled by Emscripten), and I find some performance differences between wasmer and other 3 runtimes: the execution time(collected by perf-tool, probe begins when starting to execute the wasm code(inner_module_run in wasmer) and end in sched:sched_process_exit) in wasmer is 4x slower than which in wasmtime.

• wasmer: 136486.78 us
• wasmtime: 30420.03 us
• wasmedge(AOT): 23816.45 us
• wamr(AOT): 20412.60 us

#include <stdio.h>
#include <sys/time.h>

typedef struct timeval timeval;
timeval tv;

static void repeat(int count) {
  int len = 50;
  do {
    gettimeofday(&tv, NULL);
    count -= len;
    printf("%d\n", tv.tv_usec);
  } while (count >= 0);
}

int main() {
  repeat(500000);
  return 0;
}

Hardware & OS

• Ubuntu 20.04
• CPU: Intel(R) Core(TM) i5-9500T CPU @ 2.20GHz
• Memory: 32GB

Emscripten

• emcc (Emscripten gcc/clang-like replacement + linker emulating GNU ld) 3.1.24 (68a9f990429e0bcfb63b1cde68bad792554350a5) clang version 16.0.0 (https://github.com/llvm/llvm-project 277c382760bf9575cfa2eac73d5ad1db91466d3f) Target: wasm32-unknown-emscripten Thread model: posix

Wasm runtime version

• wasmer: wasmer 3.2.0-alpha.1
• wasmtime: wasmtime-cli 8.0.0
• wasmedge: build from commit 381b7b28049b968297e6a585b92d1cba955def66
• wamr: iwasm 1.1.2

Additional details

I find that if I comment the IO(printf) in source code, the execution time of wasmer will be faster than wasmtime, so I try to replace the fd_write function to an empty function in the wasm binary just as following.

The execution times are totally changed. Because there is an another wasi call (clock_time_get) in this loop, I think the bug doesn't exist in the mechanism of calling a wasi call.

• wasmer: 2792.70 us
• wasmtime: 4796.61 us
• wasmedge: 2508.98 us
• wamr: 1940.16 us

Then, I try to comment the following code(change the written size to a fix value according to my case) and rebuild wasmer, the execution time of the original case is 8675.32 us. https://github.com/wasmerio/wasmer/blob/8a343d0f9a1d3d4b4bfe622ed345253d780a3d76/lib/wasi/src/syscalls/wasi/fd_write.rs#L132-L147

Therefore, I think maybe there are some performance bugs in the implementation of fd_write, especially in the above code.

[ptitSeb]

Thank you for this detailled ticket. Interresting findings. Can you please try again with the just released 3.2.0 version of wasmer? Also, it would be interresting to see if building the same program with the wasi sdk instead of emscripten change performances somehow.

[hungryzzz]

Hi, I try again in the 3.2.0 version of wasmer and the 3 execution times are as follow:

• 135720.06 us (original case)
• 3149.09 us (case replace fd_write)
• 8647.48 us (original case + disable some code in fd_write)

Almost the same result as the above report.

[ptitSeb]

Ok, so no changes basicaly.

[hungryzzz]

Yes, and I compile the same program using wasi-sdk-20.0, the result is still the same.

[ptitSeb]

ok, thanks for all those tests. So, it's slow access to stdout/stderr? Strange. @john-sharratt is that a normal behaviour?

[theduke]

We don't have a fast path for vectorized IO in the VirtualFile implementation, which might be part of the slowness.

But it's more likely that the asyncify wrapper and the async runtime are a significant contributor.

It would probably be helpful to run a stress test with cargo-flamegraph to get some insight.

[ptitSeb]

I'm not so sure, because the slowiness was there with 3.2.0-alpha.1, and I don't think async with present at this time.

[stale[bot]]

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[bot]]

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