Stream: git-wasmtime

Topic: wasmtime / issue #9044 Support of profile for wasm component

view this post on Zulip Wasmtime GitHub notifications bot (Jul 30 2024 at 12:58):

wynterr opened issue #9044:

Hi,

I was trying to use perf to do profiling when using wasmtime serve to serve a wasm component(compiled from https://github.com/sunfishcode/hello-wasi-http without any change). The command I run is perf record wasmtime serve --profile=perfmap target/wasm32-wasi/debug/hello_wasi_http.wasm. After calling the endpoint for a couple times, I stop the serve and use perf report --input perf.data to check the profile. However, I see this line with unresolved symbol:

1.84% wasmtime wasmtime [.] 0x000000000151eb88

Also, I find no perf-xxxx.map file under /tmp.

I wonder is profiling not supported for component serving, or anything I was not doing right?

To reproduce:

git clone https://github.com/sunfishcode/hello-wasi-http
cargo component build
perf record  wasmtime serve --profile=perfmap target/wasm32-wasi/debug/hello_wasi_http.wasm
# call the endpoint
perf report --input perf.data

view this post on Zulip Wasmtime GitHub notifications bot (Jul 30 2024 at 14:40):

alexcrichton commented on issue #9044:

To confirm, you're on Linux?

Locally I ran perf record wasmtime serve --profile perfmap ./target/wasm32-wasi/release/hello_wasi_http.wasm with perf version 6.8.1 and wasmtime-cli 23.0.1. I hit that a few times and then using perf report I see 0.88% tokio-runtime-w [JIT] tid 4066067 [.] wit_bindgen::rt::run_ctors_once::hf08958e4a83e86d1 which I believe is the symbolication.

view this post on Zulip Wasmtime GitHub notifications bot (Aug 01 2024 at 08:01):

wynterr commented on issue #9044:

To confirm, you're on Linux?

Locally I ran perf record wasmtime serve --profile perfmap ./target/wasm32-wasi/release/hello_wasi_http.wasm with perf version 6.8.1 and wasmtime-cli 23.0.1. I hit that a few times and then using perf report I see 0.88% tokio-runtime-w [JIT] tid 4066067 [.] wit_bindgen::rt::run_ctors_once::hf08958e4a83e86d1 which I believe is the symbolication.

Thanks for your reply. I'm on Linux with perf version 6.5.13 and wasmtime-cli 21.0.1 (cedf9aa0f 2024-05-22). Actually I made a mistake before and I do find the /tmp/perf-XXXX.map file now. But still seeing symbols like 0.98% wasmtime [unknown] [k] 0xffffffffc02c076f from perf report and didn't find things like wit_bindgen::rt::run_ctors_once
I'm actually quite new to this and not very sure about how to read the perf report to find the symbol that relates to things inside my wasm component.

view this post on Zulip Wasmtime GitHub notifications bot (Aug 01 2024 at 19:33):

alexcrichton commented on issue #9044:

Under "To reproduce" above are those the exact commands you used? I ran those myself locally and apart from a missing cd hello-wasi-http those worked for me. For the # call the endpoint step I ran wrk http://localhost:8080 -t 1 -d 1. In the output I see JIT symbols as expected with nothing un-symbolicated.

Perhaps perfmap support was improved or something in perf between 6.5 and 6.8? I don't know much about perf versions myself and the historicaly development of perfmap support.

view this post on Zulip Wasmtime GitHub notifications bot (Aug 05 2024 at 12:26):

wynterr commented on issue #9044:

Yes I do follow the exact commands in "To reproduce" except the missing cd hello-wasi-http. But I was using curl http://localhost:8080 to hit the endpoint.
After using wrk http://localhost:8080 -t 1 -d 1 to hit the endpoint I do find some [JIT] tid xxxx in shared objects and symbol wit_bindgen::rt::run_ctors_once, even though records with things like 0.03% tokio-runtime-w [unknown] [k] 0xffffffffc02d1028 still exist but with very small overhead.
I also tried to run curl http://localhost:8080 more times and in the end I also saw some [JIT] tid xxxx in shared objects. I guess the reason is that perf record only samples a small part of records to show so you have to make more requests to make the function call visible.

view this post on Zulip Wasmtime GitHub notifications bot (Aug 09 2024 at 06:46):

alexcrichton commented on issue #9044:

Aha! The [k] there means that it's time spent in the kernel, which I believe means that your perf invocation can't symbolize kernel stack traces. I belive that's unrelated to wasmtime profiling. If you're seeing [JIT] entries then profiling should be working.

view this post on Zulip Wasmtime GitHub notifications bot (Aug 15 2024 at 12:25):

wynterr closed issue #9044:

Hi,

I was trying to use perf to do profiling when using wasmtime serve to serve a wasm component(compiled from https://github.com/sunfishcode/hello-wasi-http without any change). The command I run is perf record wasmtime serve --profile=perfmap target/wasm32-wasi/debug/hello_wasi_http.wasm. After calling the endpoint for a couple times, I stop the serve and use perf report --input perf.data to check the profile. However, I see this line with unresolved symbol:

1.84% wasmtime wasmtime [.] 0x000000000151eb88

Also, I find no perf-xxxx.map file under /tmp.

I wonder is profiling not supported for component serving, or anything I was not doing right?

To reproduce:

git clone https://github.com/sunfishcode/hello-wasi-http
cargo component build
perf record  wasmtime serve --profile=perfmap target/wasm32-wasi/debug/hello_wasi_http.wasm
# call the endpoint
perf report --input perf.data

Last updated: Dec 23 2024 at 12:05 UTC