Surprisingly slow module compilation

[wycats]

Thanks for opening a bug report! Please answer the questions below
if they're relevant and delete this text before submitting.

• What are the steps to reproduce the issue?

I have pushed a repository at https://github.com/wycats/wand/tree/str-wasmtime. The branch str-wasmtime is self-contained.

The script ./script/all.sh runs all of the build steps. The final step, ./script/run.sh, runs an executable, which is a Rust executable that uses the wasmtime embedding API. Its source is located in ./crates/wand-cli. The Rust source for the wasm is located in ./src.

The build scripts use wasm-pack to compile and optimize the wasm. They copy the .wasm file into a data directory in the wand-cli crate, which uses include_bytes! to get the bytes.

The executable has a bunch of println!s that list out the execution steps and how much time has elapsed.

• What do you expect to happen? What does actually happen? Does it panic, and
  if so, with which assertion?

I expect the Module::new step to be relatively fast. Instead, it takes several seconds on my machine.

• Which Wasmtime version / commit hash / branch are you using?

0.22.

• If relevant, can you include some extra information about your environment?
  (Rust version, operating system, architecture...)

$ rustc --version
rustc 1.52.0-nightly (d1206f950 2021-02-15)
$ cargo --version
cargo 1.51.0-nightly (ab64d1393 2021-02-10)
$ uname -a
Linux XPS-13-2019 4.19.84-microsoft-standard #1 SMP Wed Nov 13 11:44:37 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.2 LTS
Release:        20.04
Codename:       focal

I'm on Ubuntu 20.04 inside of WSL2 on Windows 10.

[alexcrichton]

Thanks for the report! To help minimize this a bit further, this is the wasm file in question and as you've mentioned the slower-than-expected part here is Module::new, aka compiling the module.

Executing your project I see compile times of ~2s, and to poke around a bit I made a smaller script which simply compiles this module. The timings on the main branch (soon to be 0.23.0) I get are:

• old backend, opt speed - 634.ms
• old backend, opt size - 641ms
• old backend, opt none - 561ms
• new backend, opt speed - 766ms
• new backend, opt size - 752ms
• new backend, opt none - 869ms

So it looks like the new backend is not actually a win here. I'm not entirely sure how to explain the discrepancy of your project taking 2.5s to compile and an isolated script taking ~2x faster. If I use the release commit of 0.22.0 I get slightly slower compile times by ~250ms, but still not in the ~2s range.

[alexcrichton]

Aha I have found the source of the 2x slowdown over main. Your project enables logging with tracing-subscriber (no doubt because our wasi example does the same) but this has the adverse affect apparently of having log_enabled!(LogLevel::Debug) returning true. This means that very expensive debug logs like this are happening at runtime. That's accounting for a very large portion of the runtime in your example.

After commenting out the tracing-subscriber business it runs in the same amount of time I saw in my script (e.g. 2x faster)

[alexcrichton]

For further speedups beyond the numbers above there's a zulip thread going now as well -- https://bytecodealliance.zulipchat.com/#narrow/stream/225524-cranelift-new-backend/topic/wasm.20file.20that.20is.20slower.20to.20compile.20in.20new.20BE.20than.20old.20BE

[peterhuene]

So I believe the way tracing-subscriber uses the tracing-log crate also has the unfortunate consequence of formatting log strings for every level, regardless of whether or not the logger is "enabled" for that level (in this case, dependent upon the env filter respecting RUST_LOG).

The tracing-log feature is enabled by default in tracing-subscriber, which causes initialization of the global logger.

This uses a default Builder that ends up setting the maximum level to the most verbose level.

All the level-specific log macros end up as a invocation of the log! macro, which checks the level against log::max_level() to see if it needs to format the string and calls __private_api_log. __private_api_log calls Log::enabled on the logger to check to see if it wants the event; but at that point the string has already been formatted as only log::max_level is checked for that.

And since the max level is the most verbose, all strings are formatted, but the logger in tracing-log ends up telling the log crate it isn't interested in the event after all.

As Alex also noted, this would also affect any explicit checks to see if the log level is enabled (log_enabled! has the same check against log::max_level), so extra work is also being performed outside of the macro string formatting too.

Edit: my analysis was wrong as I was looking at the wrong function (accidentally was looking at __private_api_enabled and saw the &str arg and my brain assumed a formatted message rather than the target name). String formatting is delayed until the logger is asked if the level is enabled.

This only affects the log_enabled! macro it seems.

[wycats]

Your project enables logging with tracing-subscriber (no doubt because our wasi example does the same)

You're right! I stared at that line a bunch of times and kept telling myself "I copied it from an official example", and never got around to trying the whole thing with the line commented out.