wasmtime / issue #13133 Per-function compilation diagnost... · git-wasmtime

Stream: git-wasmtime

Topic: wasmtime / issue #13133 Per-function compilation diagnost...

Wasmtime GitHub notifications bot (Apr 17 2026 at 19:24):

I'll call out that I used AI to assist me with the analysis below. The desire to move us from trace=>debug from my experiences as a human. I validated that all the functions below are real and at debug. #NoAiSlop

Summary

Several modules in cranelift_codegen and wasmtime_internal_cranelift emit per-function compilation statistics at log::debug! level. For any application that embeds wasmtime and sets RUST_LOG=debug to debug their own code, these messages completely drown out all other output. I'd like to suggest downgrading these per-function messages from debug! to trace!.

Impact

I ran a workload that loaded 3 WASM modules. My actual application logic is small — the largest module has only 11 exported functions — but because WASM binaries include their full transitive dependency tree, cranelift ends up compiling ~4,100 functions total (most are from core, alloc, regex, serde_json, etc. linked into the binary). This is normal and expected for Rust-compiled WASM.

The resulting log file had 137,000 lines, of which 136,480 (99.6%) were cranelift per-function compilation diagnostics. My actual application produced only 520 lines (0.4%).

Breakdown by module:

Module Lines % of total

cranelift_codegen::timing::enabled 96,495 70.4%

cranelift_codegen::machinst::compile 16,528 12.1%

cranelift_codegen::context 12,396 9.0%

wasmtime_internal_cranelift::compiler 6,929 5.1%

cranelift_codegen::remove_constant_phis 4,132 3.0%

All cranelift 136,480 99.6%

Application logs 520 0.4%

That works out to ~33 debug log lines per compiled function. The only workaround today is to add per-module overrides like RUST_LOG=debug,cranelift_codegen=info,wasmtime_cranelift=info,... which is fragile and hard to discover.

Affected source locations

These are the log::debug! calls that emit per-function messages:

cranelift/codegen/src/timing.rs (70% of volume — 2 lines × ~12 passes × every function):
// line 265
log::debug!("   {pass}, (during {prev})");
// line 295
log::debug!("timing: Ending {}: {}ms", self.pass, duration.as_millis());
cranelift/codegen/src/context.rs (9% — CLIF instruction/block counts and egraph stats per function):
// lines 156-160
log::debug!("Number of CLIF instructions to optimize: {}", ...);
log::debug!("Number of CLIF blocks to optimize: {}", ...);
// line 387
log::debug!("egraph stats: {:?}", pass.stats);
cranelift/codegen/src/machinst/compile.rs (12% — 4 messages per function):
log::debug!("Number of CLIF instructions to lower: {}", ...);
log::debug!("Number of CLIF blocks to lower: {}", ...);
log::debug!("Number of lowered vcode instructions: {}", ...);
log::debug!("Number of lowered vcode blocks: {}", ...);
cranelift/codegen/src/remove_constant_phis.rs (3% — 1 message per function):
log::debug!("do_remove_constant_phis: done, {} iters. ...", ...);
crates/cranelift/src/compiler.rs (5% — 2 messages per function):
log::debug!("`{symbol}` translated to CLIF in {:?}", timing.total());
log::debug!("`{symbol}` compiled in {:?}", timing.total());
Suggested change

Change these per-function log::debug! calls to log::trace!. This would:

Let embedders use RUST_LOG=debug without being flooded

Keep the diagnostics fully available via RUST_LOG=trace for anyone who specifically wants them

Align with the convention that debug is for occasional diagnostics and trace is for high-volume per-operation output

If the maintainers agree with this direction, I'd be glad to help with a PR. Thank you for all the great work on cranelift and wasmtime!

Module	Lines	% of total
`cranelift_codegen::timing::enabled`	96,495	70.4%
`cranelift_codegen::machinst::compile`	16,528	12.1%
`cranelift_codegen::context`	12,396	9.0%
`wasmtime_internal_cranelift::compiler`	6,929	5.1%
`cranelift_codegen::remove_constant_phis`	4,132	3.0%
All cranelift	136,480	99.6%
Application logs	520	0.4%

Wasmtime GitHub notifications bot (Apr 17 2026 at 19:48):

bjorn3 commented on issue #13133:

Both env_logger and tracing-subscriber allow filtering log messages based on the crate/module they come from using RUST_LOG=my_crate or RUST_LOG=my_crate::some_module=debug. You could also do something like RUST_LOG=debug,cranelift-codegen=info to get debug logs, but restrict cranelift-codegen to info logs.

Wasmtime GitHub notifications bot (Apr 17 2026 at 19:50):

cfallin commented on issue #13133:

In addition to bjorn3's note (your writeup describes crate-level filtering as "fragile" but it's a pretty standard use of logging infra) I'll note that whether info should be trace or debug is kind of a fuzzy line in my head at least; we use debug! for some "higher-level" info (from the point of view of us, the compiler authors!), the distinction has been useful to us at times, and I'm not aware of a standard for when libraries should or shouldn't use debug or trace. (If there is a reference to idioms here, I'd be interested to read it and learn what others do!).

To be clear I'm open to this if consensus is that a library really shouldn't do this; but on its own, a desire for debug to be application-level only seems a bit too far to me.

Wasmtime GitHub notifications bot (Apr 17 2026 at 20:29):

jspaith commented on issue #13133:

Thanks for super fast responses @bjorn3 & @cfallin .

We will workaround this at our level by turning the defaults down to info going forward so we won't be impacted on this, but to my eye at least these still feel like trace. I won't push back further on this. But...

RE the reference, https://docs.rs/log/latest/log/enum.Level.html from Rust itself
Debug = 4
The “debug” level.

Designates lower priority information.

Trace = 5
The “trace” level.

Designates very low priority, often extremely verbose, information.
I'm obviously not a compiler guy (God bless by the way, I'm an OS developer in my day and compilers were/still magic) but from my level at app these seem to fit into extremely verbose if only based on line count versus % my app and all the other crates it loads vs wasm.

More in depth I found https://sematext.com/blog/logging-levels/ which suggest something similar.

Wasmtime GitHub notifications bot (Apr 17 2026 at 20:33):

cfallin commented on issue #13133:

Thanks -- yep, I guess I'm curious more how libraries generally approach this. I guess verbosity is relative to the context, too -- typically when we develop/debug/optimize Cranelift we're compiling one or a few functions at most, so the tracelog is very verbose and covers every IR query/manipulation more or less, while the debug-level output contains a few summary stats.

What I think might make sense is to build a macro analogous to our trace! macro and then use this debug! rather than log::debug! throughout; so in release builds, you won't get this output. Does that seem reasonable?

Wasmtime GitHub notifications bot (Apr 17 2026 at 20:39):

jspaith commented on issue #13133:

Yes - what you propose sounds good.

For a bit more background on my component - we're a protocol gateway that primarily hosts MQTT and Kafka clients, does transforms on WASM (which is cool, again thank you all). These other crates on debug don't output that frequetnly, and their various dependencies (however rust wraps sockets, all the auth logic, background timers, ...) also output pretty infrequently. I wouldn't leave debug on in production as its too much but for standard day-to-day dev as well as our gate runs debug is manageable.

Thanks again

Wasmtime GitHub notifications bot (Apr 17 2026 at 20:50):

vadim-kovalyov commented on issue #13133:

Just my 2c: As an application-level developer, I'm always frustrated when I enable RUST_LOG=debug and the output is overwhelmed by library internals I don't understand or care about. For that reason, when I write internal libraries, I exclusively use trace! for logs. If someone needs to debug my library within their app, they can explicitly enable trace for my crate. Otherwise, it's just noise.

That said, I'd push back against stripping these logs from release builds entirely. If I do need to debug a lib in a release binary, I want the ability to flip on trace logs for that crate. Downgrading to trace! is the right call IMO: it keeps the data available without
polluting everyone's default debug output.

Wasmtime GitHub notifications bot (Apr 17 2026 at 21:04):

bjorn3 commented on issue #13133:

Doesn't trace generally get disabled in release builds?

Wasmtime GitHub notifications bot (Apr 17 2026 at 21:11):

cfallin commented on issue #13133:

Our trace! does, yes, because we found observable performance impact to leaving it in with the conditional checks. I'm also not so sure I like the idea of some output always going out with the trace level, and other output conditionally going out with the trace level. And I'll note that the output that we currently have at trace level is really horrendously detailed compilation output -- nothing that anyone reasonable would want to see from production, IMHO. Things like "I am now visiting this basic block and this SSA value is ..." It's absolutely the right call to exclude that from release builds. I think the "leave it in in case you need to debug in production" viewpoint is very valid for a lot of logic, but IMHO is too abstract and generic to really be useful here.

I think that I'd be happy to take a PR that makes our debug-level output gated on debug build or tracing feature, as our trace-level output is now. (And anyone who wants to retain the option to see it dynamically can enable the feature.) @jspaith happy to review if you want to send one!

Wasmtime GitHub notifications bot (Apr 20 2026 at 16:56):

jspaith commented on issue #13133:

Thank you -- I see two ways to solve this. I think OptionA below is better, but you're the maintainers so if you want OptionB it solves my problems too so I'll happily do a PR for whichever you prefer.

Background

To step back on requirements here:
Pri1:

Req1.A Make this so maintainers can continue to maintain WASM time with logs they need to make all this happen.

Req1.B Remove the overwhelming debug! by default for app devs (initial issue here)

Pri2:

Req2.A Make it so if a customer hits an issue in field, they can easily flip on extra logging to give maintainers an issue with existing rust log vocabulary and not needing to get into debug builds, feature flags, etc. Even if feature flags are easy on a dev box, if I have a customer hitting issues that I'd need to get logs back to wasm devs for root analysis I (and most app devs on observable systems) can give them log updates to change but having them to feature flag changes isn't always practical.

So possible fixes:

OptionA

Option A -- we move log::debug! macros to log::trace!. In the hot paths above, and probably everywhere in components that reference them. (I'd tend to leave stuff like fuzzing and all alone as it doesn't seem hot path?) That alone solves Req1.B, Req2.A. But... it makes it a pain for you guys when you want to not get overwhelmed with logs; you had these at trace and debug for a reason.

So proposal here is to add a target field to all these things (see https://docs.rs/tracing/latest/tracing/#configuring-attributes), so this becomes something like
log::trace!(target: SOME_NAME_WE_AGREE_ON, "Number of CLIF instructions to optimize: {}", ...);
This maybe(?) gives us Req1.A, since you can specify RUST_LOG=crate_lift_wasm_env_whatever:SOME_NAME_WE_AGREE_ON=trace; and get the more "interesting" traces, but all the log::trace I'm leaving alone would not be picked up by this.

Option B

OptionB would be as proposed above, with a macro rules!debug that would be added where this would be compiled out. You get Req1.A and Req1.B but lose Req2.A.

There are already many log::trace! without the macros in the code - though I can't speak to their use on hot paths. So I worry a bit demoting these debug all the way out of the product without a feature flag.

But... ultimately you as maintainers are only ones who can balance Req2.A versus how much anything I imagine complicates Req1.A.

Last updated: May 03 2026 at 22:13 UTC