bytecodealliance / bytecodealliance/wasmtime
Per-function compilation diagnostics in cranelift_codegen should be trace, not debug
- Dominant language
- Rust
- Stars
- 18.6k
- Forks
- 1.8k
- Avg merge
- 1d 19h
- Merged PRs (30d)
- 121
Description
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):
```rust
// 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):
```rust
// 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):
```rust
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):
```rust
log::debug!("do_remove_constant_phis: done, {} iters. ...", ...);
```
**`crates/cranelift/src/compiler.rs`** (5% — 2 messages per function):
```rust
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!
Contributor guide
Assessment
This issue has not been assessed yet.