T0b1/wasmtime
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

cranelift: Move most debug-level logs to the trace level

Browse Source 
Cranelift crates have historically been much more verbose with debug-level
logging than most other crates in the Rust ecosystem. We log things like how
many parameters a basic block has, the color of virtual registers during
regalloc, etc. Even for Cranelift hackers, these things are largely only useful
when hacking specifically on Cranelift and looking at a particular test case,
not even when using some Cranelift embedding (such as Wasmtime).

Most of the time, when people want logging for their Rust programs, they do
something like:

    RUST_LOG=debug cargo run

This means that they get all that mostly not useful debug logging out of
Cranelift. So they might want to disable logging for Cranelift, or change it to
a higher log level:

    RUST_LOG=debug,cranelift=info cargo run

The problem is that this is already more annoying to type that `RUST_LOG=debug`,
and that Cranelift isn't one single crate, so you actually have to play
whack-a-mole with naming all the Cranelift crates off the top of your head,
something more like this:

    RUST_LOG=debug,cranelift=info,cranelift_codegen=info,cranelift_wasm=info,...

Therefore, we're changing most of the `debug!` logs into `trace!` logs: anything
that is very Cranelift-internal, unlikely to be useful/meaningful to the
"average" Cranelift embedder, or prints a message for each instruction visited
during a pass. On the other hand, things that just report a one line statistic
for a whole pass, for example, are left as `debug!`. The more verbose the log
messages are, the higher the bar they must clear to be `debug!` rather than
`trace!`.
This commit is contained in:
Nick Fitzgerald
2021-07-26 11:50:16 -07:00
parent ebbe399725
commit 4283d2116d
26 changed files with 156 additions and 166 deletions
Download Patch File Download Diff File Expand all files Collapse all files

27
cranelift/codegen/src/regalloc/coalescing.rs
View File

@@ -22,7 +22,6 @@ use core::cmp;
use core::fmt;
use core::iter;
use core::slice;
use log::debug;
// # Implementation
//
@@ -116,7 +115,7 @@ impl Coalescing {
virtregs: &mut VirtRegs,
) {
let _tt = timing::ra_cssa();
debug!("Coalescing for:\n{}", func.display(isa));
log::trace!("Coalescing for:\n{}", func.display(isa));
self.preorder.compute(domtree, &func.layout);
let mut context = Context {
isa,
@@ -185,7 +184,7 @@ impl<'a> Context<'a> {
continue;
}
debug!(
log::trace!(
" - checking {} params at back-edge {}: {}",
num_params,
pred_block,
@@ -225,7 +224,7 @@ impl<'a> Context<'a> {
if Some(def_block) == self.func.layout.entry_block()
&& self.func.signature.params[def_num].location.is_stack()
{
debug!("-> isolating function stack parameter {}", arg);
log::trace!("-> isolating function stack parameter {}", arg);
let new_arg = self.isolate_arg(pred_block, pred_inst, argnum, arg);
self.virtregs.union(param, new_arg);
continue;
@@ -294,7 +293,7 @@ impl<'a> Context<'a> {
let inst = pos.built_inst();
self.liveness.move_def_locally(param, inst);
debug!(
log::trace!(
"-> inserted {}, following {}({}: {})",
pos.display_inst(inst),
block,
@@ -364,7 +363,7 @@ impl<'a> Context<'a> {
pos.func.dfg.inst_variable_args_mut(pred_inst)[argnum] = copy;
debug!(
log::trace!(
"-> inserted {}, before {}: {}",
pos.display_inst(inst),
pred_block,
@@ -380,7 +379,7 @@ impl<'a> Context<'a> {
/// closure of the relation formed by block parameter-argument pairs found by `union_find_block()`.
fn finish_union_find(&mut self) {
self.virtregs.finish_union_find(None);
debug!("After union-find phase:{}", self.virtregs);
log::trace!("After union-find phase:{}", self.virtregs);
}
}
@@ -411,7 +410,7 @@ impl<'a> Context<'a> {
fn check_vreg(&mut self, vreg: VirtReg) -> bool {
// Order the values according to the dominator pre-order of their definition.
let values = self.virtregs.sort_values(vreg, self.func, self.preorder);
debug!("Checking {} = {}", vreg, DisplayList(values));
log::trace!("Checking {} = {}", vreg, DisplayList(values));
// Now push the values in order to the dominator forest.
// This gives us the closest dominating value def for each of the values.
@@ -432,7 +431,7 @@ impl<'a> Context<'a> {
// `value`, we only have to check if it overlaps the definition.
if self.liveness[parent.value].overlaps_def(node.def, node.block, &self.func.layout) {
// The two values are interfering, so they can't be in the same virtual register.
debug!("-> interference: {} overlaps def of {}", parent, value);
log::trace!("-> interference: {} overlaps def of {}", parent, value);
return false;
}
}
@@ -456,7 +455,7 @@ impl<'a> Context<'a> {
self.cfg,
self.preorder,
);
debug!(
log::trace!(
"Synthesizing {} from {} branches and params {}",
vreg,
self.vcopies.branches.len(),
@@ -544,7 +543,7 @@ impl<'a> Context<'a> {
}
let _vreg = self.virtregs.unify(self.values);
debug!("-> merged into {} = {}", _vreg, DisplayList(self.values));
log::trace!("-> merged into {} = {}", _vreg, DisplayList(self.values));
true
}
@@ -566,7 +565,7 @@ impl<'a> Context<'a> {
// registers and the filtered virtual copies.
let v0 = self.virtregs.congruence_class(&param);
let v1 = self.virtregs.congruence_class(&arg);
debug!(
log::trace!(
" - set 0: {}\n - set 1: {}",
DisplayList(v0),
DisplayList(v1)
@@ -618,7 +617,7 @@ impl<'a> Context<'a> {
if node.set_id != parent.set_id
&& self.liveness[parent.value].reaches_use(inst, node.block, &self.func.layout)
{
debug!(
log::trace!(
" - interference: {} overlaps vcopy at {}:{}",
parent,
node.block,
@@ -643,7 +642,7 @@ impl<'a> Context<'a> {
&& self.liveness[parent.value].overlaps_def(node.def, node.block, &self.func.layout)
{
// The two values are interfering.
debug!(" - interference: {} overlaps def of {}", parent, node.value);
log::trace!(" - interference: {} overlaps def of {}", parent, node.value);
return false;
}
}

41
cranelift/codegen/src/regalloc/coloring.rs
View File

@@ -59,7 +59,6 @@ use crate::regalloc::register_set::RegisterSet;
use crate::regalloc::solver::{Solver, SolverError};
use crate::timing;
use core::mem;
use log::debug;
/// Data structures for the coloring pass.
///
@@ -136,7 +135,7 @@ impl Coloring {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_coloring();
debug!("Coloring for:\n{}", func.display(isa));
log::trace!("Coloring for:\n{}", func.display(isa));
let mut ctx = Context {
usable_regs: isa.allocatable_registers(func),
uses_pinned_reg: isa.flags().enable_pinned_reg(),
@@ -176,7 +175,7 @@ impl<'a> Context<'a> {
/// Visit `block`, assuming that the immediate dominator has already been visited.
fn visit_block(&mut self, block: Block, tracker: &mut LiveValueTracker) {
debug!("Coloring {}:", block);
log::trace!("Coloring {}:", block);
let mut regs = self.visit_block_header(block, tracker);
tracker.drop_dead_params();
@@ -209,7 +208,7 @@ impl<'a> Context<'a> {
if opcode.is_branch() {
// The next instruction is necessarily an unconditional branch.
if let Some(branch) = self.cur.next_inst() {
debug!(
log::trace!(
"Skip coloring {}\n from {}\n with diversions {}",
self.cur.display_inst(branch),
regs.input.display(&self.reginfo),
@@ -230,7 +229,7 @@ impl<'a> Context<'a> {
// Transfer the diversion to the next block.
self.divert
.save_for_block(&mut self.cur.func.entry_diversions, target);
debug!(
log::trace!(
"Set entry-diversion for {} to\n {}",
target,
self.divert.display(&self.reginfo)
@@ -273,7 +272,7 @@ impl<'a> Context<'a> {
// Copy the content of the registered diversions to be reused at the
// entry of this basic block.
self.divert.at_block(&self.cur.func.entry_diversions, block);
debug!(
log::trace!(
"Start {} with entry-diversion set to\n {}",
block,
self.divert.display(&self.reginfo)
@@ -300,7 +299,7 @@ impl<'a> Context<'a> {
let mut regs = AvailableRegs::new(&self.usable_regs);
for lv in live.iter().filter(|lv| !lv.is_dead) {
debug!(
log::trace!(
"Live-in: {}:{} in {}",
lv.value,
lv.affinity.display(&self.reginfo),
@@ -426,7 +425,7 @@ impl<'a> Context<'a> {
tracker: &mut LiveValueTracker,
regs: &mut AvailableRegs,
) -> bool {
debug!(
log::trace!(
"Coloring {}\n from {}",
self.cur.display_inst(inst),
regs.input.display(&self.reginfo),
@@ -490,7 +489,7 @@ impl<'a> Context<'a> {
continue;
}
debug!(
log::trace!(
" kill {} in {} ({} {})",
lv.value,
self.reginfo.display_regunit(reg),
@@ -508,7 +507,7 @@ impl<'a> Context<'a> {
}
// This aligns with the " from" line at the top of the function.
debug!(" glob {}", regs.global.display(&self.reginfo));
log::trace!(" glob {}", regs.global.display(&self.reginfo));
// This flag is set when the solver failed to find a solution for the global defines that
// doesn't interfere with `regs.global`. We need to rewrite all of `inst`s global defines
@@ -564,7 +563,7 @@ impl<'a> Context<'a> {
.solver
.quick_solve(&regs.global, is_reload)
.unwrap_or_else(|_| {
debug!("quick_solve failed for {}", self.solver);
log::trace!("quick_solve failed for {}", self.solver);
self.iterate_solution(
throughs,
&regs.global,
@@ -606,7 +605,7 @@ impl<'a> Context<'a> {
regs.input = output_regs;
for lv in defs {
let loc = self.cur.func.locations[lv.value];
debug!(
log::trace!(
" color {} -> {}{}",
lv.value,
loc.display(&self.reginfo),
@@ -869,7 +868,7 @@ impl<'a> Context<'a> {
let toprc = self.reginfo.toprc(rci);
let reg = self.divert.reg(lv.value, &self.cur.func.locations);
if self.solver.is_fixed_input_conflict(toprc, reg) {
debug!(
log::trace!(
"adding var to divert fixed input conflict for {}",
toprc.info.display_regunit(reg)
);
@@ -895,7 +894,7 @@ impl<'a> Context<'a> {
ConstraintKind::FixedReg(reg) | ConstraintKind::FixedTied(reg) => {
self.add_fixed_output(lv.value, constraint.regclass, reg, throughs);
if !lv.is_local && !global_regs.is_avail(constraint.regclass, reg) {
debug!(
log::trace!(
"Fixed output {} in {}:{} is not available in global regs",
lv.value,
constraint.regclass,
@@ -931,7 +930,7 @@ impl<'a> Context<'a> {
let rc = self.reginfo.rc(rci);
self.add_fixed_output(lv.value, rc, reg, throughs);
if !lv.is_local && !global_regs.is_avail(rc, reg) {
debug!(
log::trace!(
"ABI output {} in {}:{} is not available in global regs",
lv.value,
rc,
@@ -1010,7 +1009,7 @@ impl<'a> Context<'a> {
// We need to make sure that fixed output register is compatible with the
// global register set.
if !lv.is_local && !global_regs.is_avail(constraint.regclass, reg) {
debug!(
log::trace!(
"Tied output {} in {}:{} is not available in global regs",
lv.value,
constraint.regclass,
@@ -1047,7 +1046,7 @@ impl<'a> Context<'a> {
debug_assert!(added, "Ran out of registers in {}", rc);
}
Err(SolverError::Global(_value)) => {
debug!(
log::trace!(
"Not enough global registers for {}, trying as local",
_value
);
@@ -1062,7 +1061,7 @@ impl<'a> Context<'a> {
/// Try to add an `rc` variable to the solver from the `throughs` set.
fn try_add_var(&mut self, rc: RegClass, throughs: &[LiveValue]) -> bool {
debug!("Trying to add a {} reg from {} values", rc, throughs.len());
log::trace!("Trying to add a {} reg from {} values", rc, throughs.len());
for lv in throughs {
if let Affinity::Reg(rci) = lv.affinity {
@@ -1206,7 +1205,7 @@ impl<'a> Context<'a> {
/// the constraints on the instruction operands.
///
fn replace_global_defines(&mut self, inst: Inst, tracker: &mut LiveValueTracker) {
debug!("Replacing global defs on {}", self.cur.display_inst(inst));
log::trace!("Replacing global defs on {}", self.cur.display_inst(inst));
// We'll insert copies *after `inst`. Our caller will move the cursor back.
self.cur.next_inst();
@@ -1253,14 +1252,14 @@ impl<'a> Context<'a> {
lv.endpoint = copy;
lv.is_local = true;
debug!(
log::trace!(
" + {} with {} in {}",
self.cur.display_inst(copy),
local,
loc.display(&self.reginfo)
);
}
debug!("Done: {}", self.cur.display_inst(inst));
log::trace!("Done: {}", self.cur.display_inst(inst));
}
/// Process kills on a ghost instruction.

5
cranelift/codegen/src/regalloc/reload.rs
View File

@@ -22,7 +22,6 @@ use crate::regalloc::liveness::Liveness;
use crate::timing;
use crate::topo_order::TopoOrder;
use alloc::vec::Vec;
use log::debug;
/// Reusable data structures for the reload pass.
pub struct Reload {
@@ -73,7 +72,7 @@ impl Reload {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_reload();
debug!("Reload for:\n{}", func.display(isa));
log::trace!("Reload for:\n{}", func.display(isa));
let mut ctx = Context {
cur: EncCursor::new(func, isa),
encinfo: isa.encoding_info(),
@@ -120,7 +119,7 @@ impl<'a> Context<'a> {
}
fn visit_block(&mut self, block: Block, tracker: &mut LiveValueTracker) {
debug!("Reloading {}:", block);
log::trace!("Reloading {}:", block);
self.visit_block_header(block, tracker);
tracker.drop_dead_params();

31
cranelift/codegen/src/regalloc/solver.rs
View File

@@ -109,7 +109,6 @@ use core::cmp;
use core::fmt;
use core::mem;
use core::u16;
use log::debug;
/// A variable in the constraint problem.
///
@@ -534,7 +533,7 @@ impl Solver {
/// In either case, `to` will not be available for variables on the input side of the
/// instruction.
pub fn reassign_in(&mut self, value: Value, rc: RegClass, from: RegUnit, to: RegUnit) {
debug!(
log::trace!(
"reassign_in({}:{}, {} -> {})",
value,
rc,
@@ -547,7 +546,7 @@ impl Solver {
// added as a variable previously. A fixed constraint beats a variable, so convert it.
if let Some(idx) = self.vars.iter().position(|v| v.value == value) {
let v = self.vars.remove(idx);
debug!("-> converting variable {} to a fixed constraint", v);
log::trace!("-> converting variable {} to a fixed constraint", v);
// The spiller is responsible for ensuring that all constraints on the uses of a
// value are compatible.
debug_assert!(
@@ -580,7 +579,7 @@ impl Solver {
/// This function can only be used before calling `inputs_done()`. Afterwards, more input-side
/// variables can be added by calling `add_killed_var()` and `add_through_var()`
pub fn add_var(&mut self, value: Value, constraint: RegClass, from: RegUnit) {
debug!(
log::trace!(
"add_var({}:{}, from={})",
value,
constraint,
@@ -595,7 +594,7 @@ impl Solver {
///
/// This function should be called after `inputs_done()` only. Use `add_var()` before.
pub fn add_killed_var(&mut self, value: Value, rc: RegClass, from: RegUnit) {
debug!(
log::trace!(
"add_killed_var({}:{}, from={})",
value,
rc,
@@ -610,7 +609,7 @@ impl Solver {
///
/// This function should be called after `inputs_done()` only. Use `add_var()` before.
pub fn add_through_var(&mut self, value: Value, rc: RegClass, from: RegUnit) {
debug!(
log::trace!(
"add_through_var({}:{}, from={})",
value,
rc,
@@ -631,7 +630,7 @@ impl Solver {
if let Some(v) = self.vars.iter_mut().find(|v| v.value == value) {
// We have an existing variable entry for `value`. Combine the constraints.
if let Some(rc) = v.constraint.intersect(rc) {
debug!("-> combining constraint with {} yields {}", v, rc);
log::trace!("-> combining constraint with {} yields {}", v, rc);
v.constraint = rc;
return;
} else {
@@ -643,17 +642,17 @@ impl Solver {
// No variable, then it must be a fixed reassignment.
if let Some(a) = self.assignments.get(value) {
debug!("-> already fixed assignment {}", a);
log::trace!("-> already fixed assignment {}", a);
debug_assert!(rc.contains(a.to), "Incompatible constraints for {}", value);
return;
}
debug!("{}", self);
log::trace!("{}", self);
panic!("Wrong from register for {}", value);
}
let new_var = Variable::new_live(value, rc, from, live_through);
debug!("-> new var: {}", new_var);
log::trace!("-> new var: {}", new_var);
self.regs_in.free(rc, from);
if self.inputs_done && live_through {
@@ -769,7 +768,7 @@ impl Solver {
if is_global {
let mut new_var = Variable::new_live(value, rc, reg, true);
new_var.is_global = true;
debug!("add_tied_input: new tied-global value: {}", new_var);
log::trace!("add_tied_input: new tied-global value: {}", new_var);
self.vars.push(new_var);
self.regs_in.free(rc, reg);
} else {
@@ -900,7 +899,7 @@ impl Solver {
)
});
debug!("real_solve for {}", self);
log::trace!("real_solve for {}", self);
self.find_solution(global_regs, is_reload)
}
@@ -1000,7 +999,7 @@ impl Solver {
.extend(self.assignments.values().filter_map(Move::with_assignment));
if !self.moves.is_empty() {
debug!("collect_moves: {}", DisplayList(&self.moves));
log::trace!("collect_moves: {}", DisplayList(&self.moves));
}
}
@@ -1042,7 +1041,7 @@ impl Solver {
if let Some((rc, reg)) = m.from_reg() {
avail.free(rc, reg);
}
debug!("move #{}: {}", i, m);
log::trace!("move #{}: {}", i, m);
i += 1;
continue;
}
@@ -1076,7 +1075,7 @@ impl Solver {
let m = self.moves[i].clone();
let toprc = m.rc().toprc();
if let Some(reg) = avail.iter(toprc).next() {
debug!(
log::trace!(
"breaking cycle at {} with available {} register {}",
m,
toprc,
@@ -1107,7 +1106,7 @@ impl Solver {
// a last resort.
let slot = num_spill_slots;
num_spill_slots += 1;
debug!("breaking cycle at {} with slot {}", m, slot);
log::trace!("breaking cycle at {} with slot {}", m, slot);
let old_to_reg = self.moves[i].change_to_spill(slot);
self.fills.push(Move::Fill {
value: m.value(),

27
cranelift/codegen/src/regalloc/spilling.rs
View File

@@ -29,7 +29,6 @@ use crate::timing;
use crate::topo_order::TopoOrder;
use alloc::vec::Vec;
use core::fmt;
use log::debug;
/// Return a top-level register class which contains `unit`.
fn toprc_containing_regunit(unit: RegUnit, reginfo: &RegInfo) -> RegClass {
@@ -100,7 +99,7 @@ impl Spilling {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_spilling();
debug!("Spilling for:\n{}", func.display(isa));
log::trace!("Spilling for:\n{}", func.display(isa));
let reginfo = isa.register_info();
let usable_regs = isa.allocatable_registers(func);
let mut ctx = Context {
@@ -128,7 +127,7 @@ impl<'a> Context<'a> {
}
fn visit_block(&mut self, block: Block, tracker: &mut LiveValueTracker) {
debug!("Spilling {}:", block);
log::trace!("Spilling {}:", block);
self.cur.goto_top(block);
self.visit_block_header(block, tracker);
tracker.drop_dead_params();
@@ -205,12 +204,14 @@ impl<'a> Context<'a> {
if let Affinity::Reg(rci) = lv.affinity {
let rc = self.reginfo.rc(rci);
'try_take: while let Err(mask) = self.pressure.take_transient(rc) {
debug!("Need {} reg for block param {}", rc, lv.value);
log::trace!("Need {} reg for block param {}", rc, lv.value);
match self.spill_candidate(mask, liveins) {
Some(cand) => {
debug!(
log::trace!(
"Spilling live-in {} to make room for {} block param {}",
cand, rc, lv.value
cand,
rc,
lv.value
);
self.spill_reg(cand);
}
@@ -218,7 +219,7 @@ impl<'a> Context<'a> {
// We can't spill any of the live-in registers, so we have to spill an
// block argument. Since the current spill metric would consider all the
// block arguments equal, just spill the present register.
debug!("Spilling {} block argument {}", rc, lv.value);
log::trace!("Spilling {} block argument {}", rc, lv.value);
// Since `spill_reg` will free a register, add the current one here.
self.pressure.take(rc);
@@ -236,7 +237,7 @@ impl<'a> Context<'a> {
}
fn visit_inst(&mut self, inst: Inst, block: Block, tracker: &mut LiveValueTracker) {
debug!("Inst {}, {}", self.cur.display_inst(inst), self.pressure);
log::trace!("Inst {}, {}", self.cur.display_inst(inst), self.pressure);
debug_assert_eq!(self.cur.current_inst(), Some(inst));
debug_assert_eq!(self.cur.current_block(), Some(block));
@@ -284,7 +285,7 @@ impl<'a> Context<'a> {
if op.kind != ConstraintKind::Stack {
// Add register def to pressure, spill if needed.
while let Err(mask) = self.pressure.take_transient(op.regclass) {
debug!("Need {} reg from {} throughs", op.regclass, throughs.len());
log::trace!("Need {} reg from {} throughs", op.regclass, throughs.len());
match self.spill_candidate(mask, throughs) {
Some(cand) => self.spill_reg(cand),
None => panic!(
@@ -344,7 +345,7 @@ impl<'a> Context<'a> {
// Only collect the interesting register uses.
if reguse.fixed || reguse.tied || reguse.spilled {
debug!(" reguse: {}", reguse);
log::trace!(" reguse: {}", reguse);
self.reg_uses.push(reguse);
}
}
@@ -378,7 +379,7 @@ impl<'a> Context<'a> {
let mut reguse = RegUse::new(arg, idx, toprc.into());
reguse.fixed = true;
debug!(" reguse: {}", reguse);
log::trace!(" reguse: {}", reguse);
self.reg_uses.push(reguse);
}
}
@@ -452,7 +453,7 @@ impl<'a> Context<'a> {
if need_copy || ru.spilled {
let rc = self.reginfo.rc(ru.rci);
while let Err(mask) = self.pressure.take_transient(rc) {
debug!("Copy of {} reg causes spill", rc);
log::trace!("Copy of {} reg causes spill", rc);
// Spill a live register that is *not* used by the current instruction.
// Spilling a use wouldn't help.
//
@@ -535,7 +536,7 @@ impl<'a> Context<'a> {
let rc = self.reginfo.rc(rci);
self.pressure.free(rc);
self.spills.push(value);
debug!("Spilled {}:{} -> {}", value, rc, self.pressure);
log::trace!("Spilled {}:{} -> {}", value, rc, self.pressure);
} else {
panic!("Cannot spill {} that was already on the stack", value);
}