Per-function compilation diagnostics in cranelift_codegen should be trace, not debug

[jspaith]

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!

[bjorn3]

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.

[cfallin]

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.

[jspaith]

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.

[cfallin]

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?

[jspaith]

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

[vadim-kovalyov]

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.

[bjorn3]

Doesn't trace generally get disabled in release builds?

[cfallin]

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!