Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Why wasmer run takes seconds to execute #4311

Closed
hirameki34 opened this issue Nov 15, 2023 · 2 comments · Fixed by #4332
Closed

Why wasmer run takes seconds to execute #4311

hirameki34 opened this issue Nov 15, 2023 · 2 comments · Fixed by #4332
Labels
🕵️ needs investigation The issue/PR needs further investigation performance ❓ question I've a question!

Comments

@hirameki34
Copy link

Summary

wasmer run a wasm file takes seconds to execute, more than other runtimes. Anything I miss?

Additional details

Hi,

I'm trying to test boot time for wasm runtimes using a noop wasm file compiled from rust:

fn main() {}

When I excute wasmer run noop.wasm, it takes much more time than other runtimes (< 50ms).

Here's the output of time wasmer run noop.wasm -q (I use -q option to avoid printing time):

real    0m0.319s
user    0m3.088s
sys     0m0.314s

Did I take wrong method to measure boot performance of the runtime?
Do I need more command options to optimize execute time for this simple wasm file?
Or how can I measure boot time for this runtime?

Thanks for your answer : )
@hirameki34 hirameki34 added the ❓ question I've a question! label Nov 15, 2023
@Arshia001 Arshia001 added 🕵️ needs investigation The issue/PR needs further investigation performance labels Nov 21, 2023
@Arshia001
Copy link
Member

Hi @Nemurenai2022, thanks for reporting this issue! Can you please run your test again with the -vvvv argument and report the output? Also, are you measuring the first run of the module or consecutive runs? The first run always includes a compilation pass which will slow things down.

@hirameki34
Copy link
Author

Hi @Arshia001,

Thanks for reply.

To make it clearly, I execute wasmer cache clean firstly, and run wasmer run -vvvv for several times. Here's my output:

First run before clean cache, it takes

real	0m0.621s
user	0m5.653s
sys	0m0.580s

and produce 11,344 lines output. I didn't paste it here, let me know if you need it.

Consecutive runs outputs:

$ time wasmer run -vvvv noop.wasm
⠁ Initializing the WebAssembly VM                                               2023-11-22T01:17:14.441825Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: enter
2023-11-22T01:17:14.441864Z DEBUG ThreadId(1619) virtual_mio::selector: orphaned event token=0
⠁ Compiling to WebAssembly                                                      2023-11-22T01:17:14.446150Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.446193Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.446222Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: close time.busy=62.7µs time.idle=17.0µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.446268Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450433Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: Cache hit! key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450621Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450643Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: close time.busy=4.37ms time.idle=7.00µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450666Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450688Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.450709Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: close time.busy=42.4µs time.idle=1.59µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:17:14.451111Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: close time.busy=9.29ms time.idle=4.30µs
2023-11-22T01:17:14.451135Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: enter
2023-11-22T01:17:14.451170Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: enter
2023-11-22T01:17:14.451217Z DEBUG ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::fs: Initializing WASI filesystem
2023-11-22T01:17:14.451306Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.fd_write
2023-11-22T01:17:14.451313Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.environ_get
2023-11-22T01:17:14.451317Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.environ_sizes_get
2023-11-22T01:17:14.451321Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.proc_exit
2023-11-22T01:17:14.451772Z 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-11-22T01:17:14.452111Z TRACE ThreadId(1603) wasmer_wasix::state::func_env: wasi[1:1]::cleanup
2023-11-22T01:17:14.452122Z TRACE ThreadId(1603) wasmer_wasix::state::env: wasi[1]:: cleaning up open file handles
2023-11-22T01:17:14.452126Z TRACE ThreadId(1603) wasmer_wasix::os::task::process: signal-process(Signal::Sigquit) pid=1
2023-11-22T01:17:14.452178Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::builder: main exit pid=1 tid=1 exit_code=ExitCode::success (error 0)
2023-11-22T01:17:14.452192Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: close time.busy=1.02ms time.idle=572ns
2023-11-22T01:17:14.452200Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: close time.busy=1.07ms time.idle=421ns

real	0m0.303s
user	0m3.044s
sys	0m0.316s

and

time wasmer run -vvvv noop/noop-rs.wasm
⠉ Initializing the WebAssembly VM                                               2023-11-22T01:28:08.602037Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: enter
⠉ Loading from "noop/noop-rs.wasm"                                              2023-11-22T01:28:08.610708Z DEBUG ThreadId(1619) virtual_mio::selector: orphaned event token=0
⠉ Compiling to WebAssembly                                                      2023-11-22T01:28:08.612178Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.612206Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.612220Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::shared: close time.busy=29.2µs time.idle=20.0µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.612250Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617316Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: Cache hit! key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617485Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617492Z DEBUG ThreadId(01) from_file:load: wasmer_wasix::runtime::module_cache::filesystem: close time.busy=5.24ms time.idle=1.74µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617512Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617519Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: enter key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617523Z DEBUG ThreadId(01) from_file:save: wasmer_wasix::runtime::module_cache::shared: close time.busy=10.1µs time.idle=1.03µs key=8A509496D4DCF7458484500E38F9F15EEA96D76A3105C47557BF84353C3696E4
2023-11-22T01:28:08.617701Z DEBUG ThreadId(01) from_file: wasmer_cli::commands::run: close time.busy=15.7ms time.idle=5.11µs
2023-11-22T01:28:08.617717Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: enter
2023-11-22T01:28:08.617757Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: enter
2023-11-22T01:28:08.617802Z DEBUG ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::fs: Initializing WASI filesystem
2023-11-22T01:28:08.617868Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.fd_write
2023-11-22T01:28:08.617873Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.environ_get
2023-11-22T01:28:08.617877Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.environ_sizes_get
2023-11-22T01:28:08.617880Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::env: import wasi_snapshot_preview1.proc_exit
2023-11-22T01:28:08.618303Z 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-11-22T01:28:08.619289Z TRACE ThreadId(19) wasmer_wasix::state::func_env: wasi[1:1]::cleanup
2023-11-22T01:28:08.619313Z TRACE ThreadId(19) wasmer_wasix::state::env: wasi[1]:: cleaning up open file handles
2023-11-22T01:28:08.619321Z TRACE ThreadId(19) wasmer_wasix::os::task::process: signal-process(Signal::Sigquit) pid=1
2023-11-22T01:28:08.619409Z TRACE ThreadId(01) execute_wasm:execute_wasi_module: wasmer_wasix::state::builder: main exit pid=1 tid=1 exit_code=ExitCode::success (error 0)
2023-11-22T01:28:08.619428Z  INFO ThreadId(01) execute_wasm:execute_wasi_module: wasmer_cli::commands::run: close time.busy=1.67ms time.idle=491ns
2023-11-22T01:28:08.619438Z  INFO ThreadId(01) execute_wasm: wasmer_cli::commands::run: close time.busy=1.72ms time.idle=381ns

real	0m0.305s
user	0m2.941s
sys	0m0.372s

Hope that helps. Thanks again!

@maminrayej maminrayej mentioned this issue Nov 28, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
🕵️ needs investigation The issue/PR needs further investigation performance ❓ question I've a question!
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

use rusty_pool instead of rayon wasmerio/wasmer
2 participants
@Arshia001 @hirameki34