bytecodealliance / bytecodealliance/wasmtime
Small difference makes suspicion performance decreasing
- Dominant language
- Rust
- Stars
- 18.6k
- Forks
- 1.8k
- Avg merge
- 1d 18h
- Merged PRs (30d)
- 126
Description
### Test Cases
[cases.zip](https://github.com/bytecodealliance/wasmtime/files/15321821/cases.zip)
### Steps to Reproduce
Hi, I run the attached two cases(`good.wasm`&`bad.wasm`) in `Wasmtime` and `WasmEdge`(AOT), and collect their execution time respectively (measured by time tool).
```shell
# command to collect execution time of wasmtime
wasmtime compile bad.wasm -o bad.cwasm
time wasmtime run --allow-precompiled bad.cwasm
# command to collect execution time of wasmedge
wasmedgec bad.wasm bad-wasmedge-aot.wasm
time wasmedge bad-wasmedge-aot.wasm
```
### Expected Results & Actual Results
For `good.wasm`, the execution time in different runtimes are as follows:
- Wasmtime: 1.17s
- WasmEdge: 0.59s
For `bad.wasm`, the execution time in different runtimes are as follows:
- Wasmtime: 6.01s
- WasmEdge: 0.59s
The difference between the attached two cases is as follow, i.e., changing the operand of `i32.add` from `i32.const 0` to `local.get 1`, which can bring 5x performance decreasing on `Wasmtime` but has no effect on `WasmEdge`.
```shell
➜ cases diff good.wat bad.wat
62c62
< i32.const 0
---
> local.get 1
```
```wat
;; good.wat
i32.const 0
i32.const 1
i32.add
;; bad.wat
local.get 1
i32.const 1
i32.add
```
At first I thought the performance decreasing was caused by the difference, because the `good` one uses a constant while the `bad` one uses a local variable which may need to fetch from memory. So I do a small experiment: repeatly calculate (`2000000000` times) an addition operation whose operand are a constant or a local variable and measure the execution time respectively. And I find that they are almost the same, `1.09s` vs. `1.1s`. Therefore, I think the above performance decreasing is caused by other reasons.
```wat
;; experiment case
(module
(type (;0;) (func))
(type (;1;) (func (param i32)))
(import "wasi_snapshot_preview1" "proc_exit" (func (;0;) (type 1)))
(func (;1;) (type 0)
(local i32 i32)
loop
;; i32.const 0
local.get 1
i32.const 1
i32.add
local.get 0
i32.add
local.tee 0
i32.const 2000000000
i32.ne
br_if 0
end
i32.const 0
call 0
unreachable)
(memory (;0;) 8192 8192)
(export "_start" (func 1))
(export "memory" (memory 0)))
```
### Profiling Information
I use Perf tool to profile the execution time and find that the hotspot is in the loop where the small difference happens, so I think the difference change some compilation strategy which may cause the performance decreasing.
```shell
Samples: 23K of event 'cycles', Event count (approx.): 21853956752
Overhead Command Shared Object Symbol
99.87% wasmtime jitted-93855-1.so [.] wasm[0]::function[2] ▒
0.02% tokio-runtime-w [kernel.kallsyms] [k] __mod_memcg_lruvec_state ▒
0.02% wasmtime ld-2.31.so [.] _dl_relocate_object ▒
0.02% wasmtime [kernel.kallsyms] [k] __do_fault ▒
0.01% wasmtime [kernel.kallsyms] [k] pmd_page_vaddr ▒
```
```shell
# the commands to profile
perf record -k mono ~/wasmtime/target/release/wasmtime run --profile jitdump --allow-precompiled bad.cwasm
perf inject --jit --input perf.data --output perf.jit.data
perf report --input perf.jit.data --no-children
```
### Versions and Environment
- Wasmtime version or commit: d0cf46a098d97bab9
- Operating system: Linux ringzzz-OptiPlex-7070 5.15.0-97-generic
- Architecture: Intel(R) Core(TM) i5-9500T CPU @ 2.20GHz
Contributor guide
Assessment
This issue has not been assessed yet.