Abnormal long execution time when running "hello world" #4201

hungryzzz · 2023-09-05T09:17:30Z

Describe the bug

Hi, I build the latest wasmer and find a very long execution time (computed by time tool) even when running simple "hello world"(as followed).

Wasmer: 2.466s
Wasmtime: 0.015s

#include <stdio.h>

int main() {
  printf("hello world\n");
  return 0;
}

I just insert some instrumentation rust code(as follow) in the wasmer project to collect which part of code take the most time, and the result is as follows. I find that wasmer spents too much time on PluggableRuntime::new().

wasmer/lib/cli/src/commands/run/wasi.rs

Line 262 in b03102d

    
           let mut rt = PluggableRuntime::new(Arc::new(TokioTaskManager::new(rt_or_handle.into())));

# output
⠴ Initializing the WebAssembly VM                                                                                                                                 
Time elapsed in PluggableRuntime::new is: 2.332459878s
hello world
Time elapsed in run_with_store_async() is: 1.510411ms
Time elapsed in execute_inner() is: 2.337409944s

// Instrumentation code
let start = Instant::now();  // Time begin

let mut rt = PluggableRuntime::new(Arc::new(TokioTaskManager::new(rt_or_handle.into())));

let duration = start.elapsed();  // Time end
println!("Time elapsed in prepare_runtime() is: {:?}", duration);  // print the duration

However, when I change another machine to repeat the above steps, the execution time is normal (almost the same as wasmtime), so I think maybe this bug is related to the physical machine. But I don't know how to do the further debug.

-> wasmer -vV
wasmer 4.1.2 (b03102d 2023-09-05)
binary: wasmer-cli
commit-hash: b03102d453547bb5d0fc0c605f57e6d4566f464a
commit-date: 2023-09-05
host: x86_64-unknown-linux-gnu
compiler: singlepass,cranelift

-> rustc -vV
rustc 1.72.0 (5680fa18f 2023-08-23)
binary: rustc
commit-hash: 5680fa18feaa87f3ff04063800aec256c3d4b4be
commit-date: 2023-08-23
host: x86_64-unknown-linux-gnu
release: 1.72.0
LLVM version: 16.0.5

-> uname -a
Linux xxx 5.15.0-69-generic #76-Ubuntu SMP Fri Mar 17 17:19:29 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Steps to reproduce

wasmer hello.wasm

hello.wasm.txt

The text was updated successfully, but these errors were encountered:

hungryzzz · 2023-09-06T07:11:46Z

I've also tried another two machine to run the "hello world" case using wasmer(all the versions are the same as above), the execution result is as follow.

It seems that the execution time is related to some features of physical machine.

# machine A

-> uname -a
Linux xxx 5.15.0-69-generic #76-Ubuntu SMP Fri Mar 17 17:19:29 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

-> time ../wasmer/target/release/wasmer hello.wasm
hello world
../wasmer/target/release/wasmer hello.wasm  22.44s user 0.69s system 2156% cpu 1.072 total

-> time ../wasmtime/target/release/wasmtime hello.wasm
hello world
../wasmtime/target/release/wasmtime hello.wasm  0.00s user 0.00s system 100% cpu 0.009 total

# machine B

-> uname -a
Linux xxx 5.15.0-69-generic #76-Ubuntu SMP Fri Mar 17 17:19:29 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

-> time ../wasmer/target/release/wasmer hello.wasm
hello world
../wasmer/target/release/wasmer hello.wasm  143.59s user 3.07s system 4769% cpu 3.075 total

-> time ../wasmtime/target/release/wasmtime hello.wasm
hello world
../wasmtime/target/release/wasmtime hello.wasm  0.01s user 0.00s system 100% cpu 0.008 total

ptitSeb · 2023-09-06T07:44:53Z

that's indeed very long. Can you try again with latest 4.2.0 that just went out yesterday?

hungryzzz · 2023-09-06T08:09:54Z

@ptitSeb I've try again with latest commit(cf51f38) of wasmer, the result is almost the same as above.

# the first mentioned machine
-> wasmer hello.wasm
⠴ Initializing the WebAssembly VM                                                                                                                                
Time elapsed in PluggableRuntime::new is: 2.368649716s
hello world
Time elapsed in run_with_store_async() is: 1.672804ms
Time elapsed in execute_inner() is: 2.374535564s

# machine A
-> time ../wasmer/target/release/wasmer hello.wasm
hello world
../wasmer/target/release/wasmer hello.wasm  22.17s user 0.77s system 2082% cpu 1.101 total

# machine B
-> time ../wasmer/target/release/wasmer hello.wasm
hello world
../wasmer/target/release/wasmer hello.wasm  146.01s user 3.15s system 4762% cpu 3.132 total

-> wasmer -vV
wasmer 4.2.0 (cf51f38 2023-09-06)
binary: wasmer-cli
commit-hash: cf51f38568bea3de369d05514640872589dd6c5e
commit-date: 2023-09-06
host: x86_64-unknown-linux-gnu
compiler: singlepass,cranelift

ptitSeb · 2023-09-12T08:43:02Z

Can you run with RUST_LOG=trace wasmer run hello.wasm and put the log here.

hungryzzz · 2023-09-18T15:35:15Z

@ptitSeb Hi, the log is as followed.

⠴ Initializing the WebAssembly VM                                                                                                                                 
Time elapsed in PluggableRuntime::new is: 2.485054208s
2023-09-18T15:32:35.461412Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: enter
⠴ Compiling to WebAssembly                                                                                                                                        
2023-09-18T15:32:35.461666Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: enter key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.461749Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: close time.busy=76.3µs time.idle=7.17µs key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.461839Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: enter key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.462116Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: Cache hit! key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.462194Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: close time.busy=347µs time.idle=13.3µs key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.462288Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: enter key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.462344Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: close time.busy=55.9µs time.idle=1.27µs key=138D0F4D7C0B591138C0BACF3E9E4CA4DC578F008D0740DB2DB947A2619DD68B
2023-09-18T15:32:35.462400Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: close time.busy=1.00ms time.idle=3.94µs
2023-09-18T15:32:35.462486Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: enter
2023-09-18T15:32:35.462564Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: enter
2023-09-18T15:32:35.462668Z DEBUG ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::fs: Initializing WASI filesystem
2023-09-18T15:32:35.462799Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.proc_exit
2023-09-18T15:32:35.462851Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.fd_write
2023-09-18T15:32:35.463748Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::func_env: initializing with layout WasiMemoryLayout { stack_upper: 1048576, stack_lower: 0, guard_size: 0, stack_size: 1048576 }
2023-09-18T15:32:35.464035Z TRACE ThreadId(6420) fd_write: wasmer_wasix::syscalls::wasi::fd_write: enter fd=1
hello world
2023-09-18T15:32:35.466374Z TRACE ThreadId(6420) fd_write: wasmer_wasix::syscalls::wasi::fd_write: return=Errno::success fd=1 nwritten=12
2023-09-18T15:32:35.466389Z TRACE ThreadId(6420) fd_write: wasmer_wasix::syscalls::wasi::fd_write: close time.busy=2.36ms time.idle=2.15µs fd=1 nwritten=12
2023-09-18T15:32:35.466424Z DEBUG ThreadId(6420) proc_exit: wasmer_wasix::syscalls::wasi::proc_exit: enter
2023-09-18T15:32:35.466432Z DEBUG ThreadId(6420) proc_exit: wasmer_wasix::syscalls::wasi::proc_exit: code=ExitCode::success (error 0)
2023-09-18T15:32:35.466447Z DEBUG ThreadId(6420) proc_exit: wasmer_wasix::syscalls::wasi::proc_exit: close time.busy=22.5µs time.idle=1.31µs
2023-09-18T15:32:35.466633Z TRACE ThreadId(6420) wasmer_wasix::state::func_env: wasi[1:1]::cleanup
2023-09-18T15:32:35.466644Z TRACE ThreadId(6420) wasmer_wasix::state::env: wasi[1]:: cleaning up open file handles
2023-09-18T15:32:35.466651Z TRACE ThreadId(6420) wasmer_wasix::os::task::process: signal-process(Signal::Sigquit) pid=1
2023-09-18T15:32:35.466689Z TRACE ThreadId(6420) wasmer_wasix::fs: closing file descriptor fd=0 inode=2 ref_cnt=1
2023-09-18T15:32:35.466702Z TRACE ThreadId(6420) wasmer_wasix::fs: closing file descriptor fd=1 inode=3 ref_cnt=1
2023-09-18T15:32:35.466712Z TRACE ThreadId(6420) wasmer_wasix::fs: closing file descriptor fd=2 inode=4 ref_cnt=1
2023-09-18T15:32:35.466721Z TRACE ThreadId(6420) wasmer_wasix::fs: weakening file descriptor fd=3 inode=1 ref_cnt=2
2023-09-18T15:32:35.466758Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::builder: main exit pid=1 tid=1 exit_code=ExitCode::success (error 0)
Time elapsed in run_with_store_async() is: 4.134068ms
2023-09-18T15:32:35.466800Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: close time.busy=4.24ms time.idle=960ns
2023-09-18T15:32:35.466832Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: close time.busy=4.35ms time.idle=690ns
Time elapsed in execute_inner() is: 2.494107278s

ptitSeb · 2023-09-18T16:26:07Z

where does this line

Time elapsed in PluggableRuntime::new is: 2.485054208s

came from?

Arshia001 · 2023-09-18T16:44:48Z

@hungryzzz are you running the official wasmer CLI? Also, it looks like wasmer_cli::commands::run: enter and wasmer_cli::commands::run: close are just 4.5 milliseconds apart, which should be the time wasmer took to execute the module. Did wasmer take 20 seconds to run? Was that delay before or after the logs started showing up?

hungryzzz · 2023-09-19T07:05:00Z

where does this line
Time elapsed in PluggableRuntime::new is: 2.485054208s
came from?

@ptitSeb I add some instrumentation code in wasmer as I wrote in the beginning.

// Instrumentation code
let start = Instant::now();  // Time begin

let mut rt = PluggableRuntime::new(Arc::new(TokioTaskManager::new(rt_or_handle.into())));

let duration = start.elapsed();  // Time end
println!("Time elapsed in prepare_runtime() is: {:?}", duration);  // print the duration

hungryzzz · 2023-09-19T07:12:02Z

@hungryzzz are you running the official wasmer CLI? Also, it looks like wasmer_cli::commands::run: enter and wasmer_cli::commands::run: close are just 4.5 milliseconds apart, which should be the time wasmer took to execute the module. Did wasmer take 20 seconds to run? Was that delay before or after the logs started showing up?

Hi, I add some instrumentation code in wasmer to record the execution time. The result is as followed.

# output
⠴ Initializing the WebAssembly VM                                                                                                                                 
Time elapsed in PluggableRuntime::new is: 2.332459878s
hello world
Time elapsed in run_with_store_async() is: 1.510411ms
Time elapsed in execute_inner() is: 2.337409944s

According to the logs, I find that let mut rt = PluggableRuntime::new(Arc::new(TokioTaskManager::new(rt_or_handle.into()))); in lib/cli/src/commands/run/wasi.rs will spend most of time.

Arshia001 · 2023-09-19T09:15:16Z

@hungryzzz thanks, that's very helpful.

hungryzzz · 2023-10-15T09:12:31Z

Actually, I found that the current version of wasmer is slower than wasmer 4.0.0.

syrusakbary · 2024-05-13T11:44:02Z

I just tested on latest main and it seems the issue is already resolved in Wasmer 4.3.0.
Please feel free to reopen if it persists on your side

ptitSeb added the priority-high High priority issue label Sep 12, 2023

ptitSeb assigned Arshia001 Sep 12, 2023

ptitSeb added this to the v4.3 milestone Sep 12, 2023

maminrayej mentioned this issue Nov 28, 2023

use rusty_pool instead of rayon #4332

Merged

syrusakbary closed this as completed May 13, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Abnormal long execution time when running "hello world" #4201

Abnormal long execution time when running "hello world" #4201

hungryzzz commented Sep 5, 2023 •

edited

Loading

hungryzzz commented Sep 6, 2023

ptitSeb commented Sep 6, 2023

hungryzzz commented Sep 6, 2023 •

edited

Loading

ptitSeb commented Sep 12, 2023

hungryzzz commented Sep 18, 2023

ptitSeb commented Sep 18, 2023

Arshia001 commented Sep 18, 2023

hungryzzz commented Sep 19, 2023

hungryzzz commented Sep 19, 2023

Arshia001 commented Sep 19, 2023

hungryzzz commented Oct 15, 2023

syrusakbary commented May 13, 2024

Abnormal long execution time when running "hello world" #4201

Abnormal long execution time when running "hello world" #4201

Comments

hungryzzz commented Sep 5, 2023 • edited Loading

Describe the bug

Steps to reproduce

hungryzzz commented Sep 6, 2023

ptitSeb commented Sep 6, 2023

hungryzzz commented Sep 6, 2023 • edited Loading

ptitSeb commented Sep 12, 2023

hungryzzz commented Sep 18, 2023

ptitSeb commented Sep 18, 2023

Arshia001 commented Sep 18, 2023

hungryzzz commented Sep 19, 2023

hungryzzz commented Sep 19, 2023

Arshia001 commented Sep 19, 2023

hungryzzz commented Oct 15, 2023

syrusakbary commented May 13, 2024

hungryzzz commented Sep 5, 2023 •

edited

Loading

hungryzzz commented Sep 6, 2023 •

edited

Loading