Fixes #404: Use log.rs and a file-per-thread logger instead of the dbg! macro;

This commit is contained in:
Benjamin Bouvier
2018-07-20 19:14:04 +02:00
committed by Dan Gohman
parent 60c2cad06e
commit a044f58cea
27 changed files with 123 additions and 221 deletions

View File

@@ -34,6 +34,8 @@ term = "0.5.1"
capstone = { version = "0.4", optional = true }
wabt = { version = "0.4", optional = true }
target-lexicon = "0.0.3"
pretty_env_logger = "0.2.4"
file-per-thread-logger = "0.1.1"
[features]
default = ["disas", "wasm"]

View File

@@ -12,6 +12,7 @@
extern crate cfg_if;
extern crate cranelift_codegen;
extern crate cranelift_filetests;
extern crate file_per_thread_logger;
extern crate cranelift_reader;
extern crate docopt;
extern crate filecheck;
@@ -19,6 +20,7 @@ extern crate filecheck;
extern crate serde_derive;
#[cfg(feature = "disas")]
extern crate capstone;
extern crate pretty_env_logger;
extern crate term;
cfg_if! {
@@ -31,6 +33,7 @@ cfg_if! {
}
extern crate target_lexicon;
use cranelift_codegen::dbg::LOG_FILENAME_PREFIX;
use cranelift_codegen::{timing, VERSION};
use docopt::Docopt;
use std::io::{self, Write};
@@ -46,16 +49,17 @@ const USAGE: &str = "
Cranelift code generator utility
Usage:
clif-util test [-vT] <file>...
clif-util cat <file>...
clif-util filecheck [-v] <file>
clif-util print-cfg <file>...
clif-util compile [-vpT] [--set <set>]... [--target <triple>] <file>...
clif-util wasm [-ctvpTs] [--set <set>]... [--target <triple>] <file>...
clif-util test [-vTd] <file>...
clif-util cat [-d] <file>...
clif-util filecheck [-vd] <file>
clif-util print-cfg [-d] <file>...
clif-util compile [-vpTd] [--set <set>]... [--target <triple>] <file>...
clif-util wasm [-ctvpTsd] [--set <set>]... [--target <triple>] <file>...
clif-util --help | --version
Options:
-v, --verbose be more verbose
-d, --debug enable debug output on stderr/stdout
-T, --time-passes
print pass timing report
-t, --just-decode
@@ -90,6 +94,7 @@ struct Args {
flag_target: String,
flag_time_passes: bool,
flag_print_size: bool,
flag_debug: bool,
}
/// A command either succeeds or fails with an error message.
@@ -106,6 +111,12 @@ fn clif_util() -> CommandResult {
})
.unwrap_or_else(|e| e.exit());
if args.flag_debug {
pretty_env_logger::init();
} else {
file_per_thread_logger::initialize(LOG_FILENAME_PREFIX);
}
// Find the sub-command to execute.
let result = if args.cmd_test {
cranelift_filetests::run(args.flag_verbose, &args.arg_file).map(|_time| ())

View File

@@ -16,6 +16,7 @@ failure = { version = "0.1.1", default-features = false, features = ["derive"] }
failure_derive = { version = "0.1.1", default-features = false }
hashmap_core = { version = "0.1.9", optional = true }
target-lexicon = { version = "0.0.3", default-features = false }
log = { version = "0.4.3", default-features = false, features = ["release_max_level_warn"] }
# It is a goal of the cranelift-codegen crate to have minimal external dependencies.
# Please don't add any unless they are essential to the task of creating binary
# machine code. Integration tests that need external dependencies can be

View File

@@ -140,7 +140,7 @@ fn relax_branch(
isa: &TargetIsa,
) -> CodeOffset {
let inst = cur.current_inst().unwrap();
dbg!(
debug!(
"Relaxing [{}] {} for {:#x}-{:#x} range",
encinfo.display(cur.func.encodings[inst]),
cur.func.dfg.display_inst(inst, isa),
@@ -156,7 +156,7 @@ fn relax_branch(
.find(|&enc| {
let range = encinfo.branch_range(enc).expect("Branch with no range");
if !range.contains(offset, dest_offset) {
dbg!(" trying [{}]: out of range", encinfo.display(enc));
debug!(" trying [{}]: out of range", encinfo.display(enc));
false
} else if encinfo.operand_constraints(enc)
!= encinfo.operand_constraints(cur.func.encodings[inst])
@@ -166,10 +166,10 @@ fn relax_branch(
// which the existing operands don't satisfy. We can't check for
// validity directly because we don't have a RegDiversions active so
// we don't know which registers are actually in use.
dbg!(" trying [{}]: constraints differ", encinfo.display(enc));
debug!(" trying [{}]: constraints differ", encinfo.display(enc));
false
} else {
dbg!(" trying [{}]: OK", encinfo.display(enc));
debug!(" trying [{}]: OK", encinfo.display(enc));
true
}
}) {

View File

@@ -54,7 +54,7 @@ pub fn shrink_instructions(func: &mut Function, isa: &TargetIsa) {
if best_enc != enc {
func.encodings[inst] = best_enc;
dbg!(
debug!(
"Shrunk [{}] to [{}] in {}, reducing the size from {} to {}",
encinfo.display(enc),
encinfo.display(best_enc),

View File

@@ -1,133 +1,8 @@
//! Debug tracing macros.
//!
//! This module defines the `dbg!` macro which works like `println!` except it writes to the
//! Cranelift tracing output file if enabled.
//!
//! Tracing can be enabled by setting the `CRANELIFT_DBG` environment variable to something
/// other than `0`.
///
/// The output will appear in files named `cranelift.dbg.*`, where the suffix is named after the
/// thread doing the logging.
#[cfg(feature = "std")]
use std::cell::RefCell;
#[cfg(feature = "std")]
use std::env;
#[cfg(feature = "std")]
use std::ffi::OsStr;
//! Debug tracing helpers.
use std::fmt;
#[cfg(feature = "std")]
use std::fs::File;
#[cfg(feature = "std")]
use std::io::{self, Write};
#[cfg(feature = "std")]
use std::sync::atomic;
#[cfg(feature = "std")]
use std::thread;
#[cfg(feature = "std")]
static STATE: atomic::AtomicIsize = atomic::ATOMIC_ISIZE_INIT;
/// Is debug tracing enabled?
///
/// Debug tracing can be enabled by setting the `CRANELIFT_DBG` environment variable to something
/// other than `0`.
///
/// This inline function turns into a constant `false` when debug assertions are disabled.
#[cfg(feature = "std")]
#[inline]
pub fn enabled() -> bool {
if cfg!(debug_assertions) {
match STATE.load(atomic::Ordering::Relaxed) {
0 => initialize(),
s => s > 0,
}
} else {
false
}
}
/// Does nothing
#[cfg(not(feature = "std"))]
#[inline]
pub fn enabled() -> bool {
false
}
/// Initialize `STATE` from the environment variable.
#[cfg(feature = "std")]
fn initialize() -> bool {
let enable = match env::var_os("CRANELIFT_DBG") {
Some(s) => s != OsStr::new("0"),
None => false,
};
if enable {
STATE.store(1, atomic::Ordering::Relaxed);
} else {
STATE.store(-1, atomic::Ordering::Relaxed);
}
enable
}
#[cfg(feature = "std")]
thread_local! {
static WRITER : RefCell<io::BufWriter<File>> = RefCell::new(open_file());
}
/// Write a line with the given format arguments.
///
/// This is for use by the `dbg!` macro.
#[cfg(feature = "std")]
pub fn writeln_with_format_args(args: fmt::Arguments) -> io::Result<()> {
WRITER.with(|rc| {
let mut w = rc.borrow_mut();
writeln!(*w, "{}", args)?;
w.flush()
})
}
/// Open the tracing file for the current thread.
#[cfg(feature = "std")]
fn open_file() -> io::BufWriter<File> {
let curthread = thread::current();
let tmpstr;
let mut path = "cranelift.dbg.".to_owned();
path.extend(
match curthread.name() {
Some(name) => name.chars(),
// The thread is unnamed, so use the thread ID instead.
None => {
tmpstr = format!("{:?}", curthread.id());
tmpstr.chars()
}
}.filter(|ch| ch.is_alphanumeric() || *ch == '-' || *ch == '_'),
);
let file = File::create(path).expect("Can't open tracing file");
io::BufWriter::new(file)
}
/// Write a line to the debug trace file if tracing is enabled.
///
/// Arguments are the same as for `printf!`.
#[cfg(feature = "std")]
#[macro_export]
macro_rules! dbg {
($($arg:tt)+) => {
if $crate::dbg::enabled() {
// Drop the error result so we don't get compiler errors for ignoring it.
// What are you going to do, log the error?
$crate::dbg::writeln_with_format_args(format_args!($($arg)+)).ok();
}
}
}
/// `dbg!` isn't supported in `no_std` mode, so expand it into nothing.
#[cfg(not(feature = "std"))]
#[macro_export]
macro_rules! dbg {
($($arg:tt)+) => {};
}
/// Prefix added to the log file names, just before the thread name or id.
pub static LOG_FILENAME_PREFIX: &str = "cranelift.dbg.";
/// Helper for printing lists.
pub struct DisplayList<'a, T>(pub &'a [T])

View File

@@ -316,7 +316,7 @@ impl Layout {
next_inst = self.insts[inst].next.expand();
}
}
dbg!("Renumbered {} program points", seq / MAJOR_STRIDE);
debug!("Renumbered {} program points", seq / MAJOR_STRIDE);
}
}

View File

@@ -270,7 +270,7 @@ where
// Reconstruct how `ty` was legalized into the `arg_type` argument.
let conversion = legalize_abi_value(ty, &arg_type);
dbg!("convert_from_abi({}): {:?}", ty, conversion);
debug!("convert_from_abi({}): {:?}", ty, conversion);
// The conversion describes value to ABI argument. We implement the reverse conversion here.
match conversion {
@@ -279,7 +279,7 @@ where
let abi_ty = ty.half_width().expect("Invalid type for conversion");
let lo = convert_from_abi(pos, abi_ty, None, get_arg);
let hi = convert_from_abi(pos, abi_ty, None, get_arg);
dbg!(
debug!(
"intsplit {}: {}, {}: {}",
lo,
pos.func.dfg.value_type(lo),
@@ -586,7 +586,7 @@ pub fn handle_return_abi(inst: Inst, func: &mut Function, cfg: &ControlFlowGraph
// the legalized signature. These values should simply be propagated from the entry block
// arguments.
if special_args > 0 {
dbg!(
debug!(
"Adding {} special-purpose arguments to {}",
special_args,
pos.func.dfg.display_inst(inst, None)

View File

@@ -49,6 +49,10 @@ extern crate failure_derive;
#[cfg_attr(test, macro_use)]
extern crate target_lexicon;
#[cfg(feature = "std")]
#[macro_use]
extern crate log;
pub use context::Context;
pub use legalizer::legalize_function;
pub use verifier::verify_function;
@@ -60,13 +64,11 @@ pub const VERSION: &str = env!("CARGO_PKG_VERSION");
#[macro_use]
pub extern crate cranelift_entity as entity;
#[macro_use]
pub mod dbg;
pub mod bforest;
pub mod binemit;
pub mod cfg_printer;
pub mod cursor;
pub mod dbg;
pub mod dominator_tree;
pub mod flowgraph;
pub mod ir;

View File

@@ -116,7 +116,7 @@ impl Coalescing {
virtregs: &mut VirtRegs,
) {
let _tt = timing::ra_cssa();
dbg!("Coalescing for:\n{}", func.display(isa));
debug!("Coalescing for:\n{}", func.display(isa));
self.preorder.compute(domtree, &func.layout);
let mut context = Context {
isa,
@@ -185,7 +185,7 @@ impl<'a> Context<'a> {
continue;
}
dbg!(
debug!(
" - checking {} params at back-edge {}: {}",
num_params,
pred_ebb,
@@ -229,7 +229,7 @@ impl<'a> Context<'a> {
if Some(def_ebb) == self.func.layout.entry_block()
&& self.func.signature.params[def_num].location.is_stack()
{
dbg!("-> isolating function stack parameter {}", arg);
debug!("-> isolating function stack parameter {}", arg);
let new_arg = self.isolate_arg(pred_ebb, pred_inst, argnum, arg);
self.virtregs.union(param, new_arg);
continue;
@@ -296,7 +296,7 @@ impl<'a> Context<'a> {
let inst = pos.built_inst();
self.liveness.move_def_locally(param, inst);
dbg!(
debug!(
"-> inserted {}, following {}({}: {})",
pos.display_inst(inst),
ebb,
@@ -365,7 +365,7 @@ impl<'a> Context<'a> {
pos.func.dfg.inst_variable_args_mut(pred_inst)[argnum] = copy;
dbg!(
debug!(
"-> inserted {}, before {}: {}",
pos.display_inst(inst),
pred_ebb,
@@ -381,7 +381,7 @@ impl<'a> Context<'a> {
/// closure of the relation formed by EBB parameter-argument pairs found by `union_find_ebb()`.
fn finish_union_find(&mut self) {
self.virtregs.finish_union_find(None);
dbg!("After union-find phase:{}", self.virtregs);
debug!("After union-find phase:{}", self.virtregs);
}
}
@@ -412,7 +412,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);
dbg!("Checking {} = {}", vreg, DisplayList(values));
debug!("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.
@@ -434,7 +434,7 @@ impl<'a> Context<'a> {
let ctx = self.liveness.context(&self.func.layout);
if self.liveness[parent.value].overlaps_def(node.def, node.ebb, ctx) {
// The two values are interfering, so they can't be in the same virtual register.
dbg!("-> interference: {} overlaps def of {}", parent, value);
debug!("-> interference: {} overlaps def of {}", parent, value);
return false;
}
}
@@ -458,7 +458,7 @@ impl<'a> Context<'a> {
self.cfg,
self.preorder,
);
dbg!(
debug!(
"Synthesizing {} from {} branches and params {}",
vreg,
self.vcopies.branches.len(),
@@ -546,7 +546,7 @@ impl<'a> Context<'a> {
}
let _vreg = self.virtregs.unify(self.values);
dbg!("-> merged into {} = {}", _vreg, DisplayList(self.values));
debug!("-> merged into {} = {}", _vreg, DisplayList(self.values));
true
}
@@ -568,7 +568,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);
dbg!(
debug!(
" - set 0: {}\n - set 1: {}",
DisplayList(v0),
DisplayList(v1)
@@ -621,7 +621,7 @@ impl<'a> Context<'a> {
if node.set_id != parent.set_id
&& self.liveness[parent.value].reaches_use(inst, node.ebb, ctx)
{
dbg!(
debug!(
" - interference: {} overlaps vcopy at {}:{}",
parent,
node.ebb,
@@ -646,7 +646,7 @@ impl<'a> Context<'a> {
&& self.liveness[parent.value].overlaps_def(node.def, node.ebb, ctx)
{
// The two values are interfering.
dbg!(" - interference: {} overlaps def of {}", parent, node.value);
debug!(" - interference: {} overlaps def of {}", parent, node.value);
return false;
}
}

View File

@@ -124,7 +124,7 @@ impl Coloring {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_coloring();
dbg!("Coloring for:\n{}", func.display(isa));
debug!("Coloring for:\n{}", func.display(isa));
let mut ctx = Context {
usable_regs: isa.allocatable_registers(func),
cur: EncCursor::new(func, isa),
@@ -156,7 +156,7 @@ impl<'a> Context<'a> {
/// Visit `ebb`, assuming that the immediate dominator has already been visited.
fn visit_ebb(&mut self, ebb: Ebb, tracker: &mut LiveValueTracker) {
dbg!("Coloring {}:", ebb);
debug!("Coloring {}:", ebb);
let mut regs = self.visit_ebb_header(ebb, tracker);
tracker.drop_dead_params();
self.divert.clear();
@@ -216,7 +216,7 @@ impl<'a> Context<'a> {
let mut regs = AvailableRegs::new(&self.usable_regs);
for lv in live.iter().filter(|lv| !lv.is_dead) {
dbg!(
debug!(
"Live-in: {}:{} in {}",
lv.value,
lv.affinity.display(&self.reginfo),
@@ -294,7 +294,7 @@ impl<'a> Context<'a> {
tracker: &mut LiveValueTracker,
regs: &mut AvailableRegs,
) -> bool {
dbg!(
debug!(
"Coloring {}\n from {}",
self.cur.display_inst(inst),
regs.input.display(&self.reginfo),
@@ -362,7 +362,7 @@ impl<'a> Context<'a> {
if let Affinity::Reg(rci) = lv.affinity {
let rc = self.reginfo.rc(rci);
let reg = self.divert.reg(lv.value, &self.cur.func.locations);
dbg!(
debug!(
" kill {} in {} ({} {})",
lv.value,
self.reginfo.display_regunit(reg),
@@ -380,7 +380,7 @@ impl<'a> Context<'a> {
}
// This aligns with the " from" line at the top of the function.
dbg!(" glob {}", regs.global.display(&self.reginfo));
debug!(" 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
@@ -419,7 +419,7 @@ impl<'a> Context<'a> {
// Finally, we've fully programmed the constraint solver.
// We expect a quick solution in most cases.
let output_regs = self.solver.quick_solve(&regs.global).unwrap_or_else(|_| {
dbg!("quick_solve failed for {}", self.solver);
debug!("quick_solve failed for {}", self.solver);
self.iterate_solution(throughs, &regs.global, &mut replace_global_defines)
});
@@ -454,7 +454,7 @@ impl<'a> Context<'a> {
regs.input = output_regs;
for lv in defs {
let loc = self.cur.func.locations[lv.value];
dbg!(
debug!(
" color {} -> {}{}",
lv.value,
loc.display(&self.reginfo),
@@ -700,7 +700,7 @@ impl<'a> Context<'a> {
ConstraintKind::FixedReg(reg) | ConstraintKind::FixedTied(reg) => {
self.add_fixed_output(lv.value, op.regclass, reg, throughs);
if !lv.is_local && !global_regs.is_avail(op.regclass, reg) {
dbg!(
debug!(
"Fixed output {} in {}:{} is not available in global regs",
lv.value,
op.regclass,
@@ -736,7 +736,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) {
dbg!(
debug!(
"ABI output {} in {}:{} is not available in global regs",
lv.value,
rc,
@@ -812,7 +812,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(op.regclass, reg) {
dbg!(
debug!(
"Tied output {} in {}:{} is not available in global regs",
lv.value,
op.regclass,
@@ -848,7 +848,7 @@ impl<'a> Context<'a> {
debug_assert!(added, "Ran out of registers in {}", rc);
}
Err(SolverError::Global(_value)) => {
dbg!(
debug!(
"Not enough global registers for {}, trying as local",
_value
);
@@ -863,7 +863,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 {
dbg!("Trying to add a {} reg from {} values", rc, throughs.len());
debug!("Trying to add a {} reg from {} values", rc, throughs.len());
for lv in throughs {
if let Affinity::Reg(rci) = lv.affinity {
@@ -995,7 +995,7 @@ impl<'a> Context<'a> {
/// the constraints on the instruction operands.
///
fn replace_global_defines(&mut self, inst: Inst, tracker: &mut LiveValueTracker) {
dbg!("Replacing global defs on {}", self.cur.display_inst(inst));
debug!("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();
@@ -1042,14 +1042,14 @@ impl<'a> Context<'a> {
lv.endpoint = copy;
lv.is_local = true;
dbg!(
debug!(
" + {} with {} in {}",
self.cur.display_inst(copy),
local,
loc.display(&self.reginfo)
);
}
dbg!("Done: {}", self.cur.display_inst(inst));
debug!("Done: {}", self.cur.display_inst(inst));
}
/// Process kills on a ghost instruction.

View File

@@ -72,7 +72,7 @@ impl Reload {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_reload();
dbg!("Reload for:\n{}", func.display(isa));
debug!("Reload for:\n{}", func.display(isa));
let mut ctx = Context {
cur: EncCursor::new(func, isa),
encinfo: isa.encoding_info(),
@@ -119,7 +119,7 @@ impl<'a> Context<'a> {
}
fn visit_ebb(&mut self, ebb: Ebb, tracker: &mut LiveValueTracker) {
dbg!("Reloading {}:", ebb);
debug!("Reloading {}:", ebb);
self.visit_ebb_header(ebb, tracker);
tracker.drop_dead_params();

View File

@@ -532,7 +532,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) {
dbg!(
debug!(
"reassign_in({}:{}, {} -> {})",
value,
rc,
@@ -545,7 +545,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);
dbg!("-> converting variable {} to a fixed constraint", v);
debug!("-> 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!(
@@ -578,7 +578,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) {
dbg!(
debug!(
"add_var({}:{}, from={})",
value,
constraint,
@@ -593,7 +593,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, constraint: RegClass, from: RegUnit) {
dbg!(
debug!(
"add_killed_var({}:{}, from={})",
value,
constraint,
@@ -608,7 +608,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, constraint: RegClass, from: RegUnit) {
dbg!(
debug!(
"add_through_var({}:{}, from={})",
value,
constraint,
@@ -635,7 +635,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(constraint) {
dbg!("-> combining constraint with {} yields {}", v, rc);
debug!("-> combining constraint with {} yields {}", v, rc);
v.constraint = rc;
return;
} else {
@@ -647,7 +647,7 @@ impl Solver {
// No variable, then it must be a fixed reassignment.
if let Some(a) = self.assignments.get(value) {
dbg!("-> already fixed assignment {}", a);
debug!("-> already fixed assignment {}", a);
debug_assert!(
constraint.contains(a.to),
"Incompatible constraints for {}",
@@ -656,12 +656,12 @@ impl Solver {
return;
}
dbg!("{}", self);
debug!("{}", self);
panic!("Wrong from register for {}", value);
}
let new_var = Variable::new_live(value, constraint, from, live_through);
dbg!("-> new var: {}", new_var);
debug!("-> new var: {}", new_var);
self.regs_in.free(constraint, from);
if self.inputs_done && live_through {
@@ -777,7 +777,7 @@ impl Solver {
if is_global {
let mut new_var = Variable::new_live(value, rc, reg, true);
new_var.is_global = true;
dbg!("add_tied_input: new tied-global value: {}", new_var);
debug!("add_tied_input: new tied-global value: {}", new_var);
self.vars.push(new_var);
self.regs_in.free(rc, reg);
} else {
@@ -899,7 +899,7 @@ impl Solver {
)
});
dbg!("real_solve for {}", self);
debug!("real_solve for {}", self);
self.find_solution(global_regs)
}
@@ -982,7 +982,7 @@ impl Solver {
.extend(self.assignments.values().filter_map(Move::with_assignment));
if !(self.moves.is_empty()) {
dbg!("collect_moves: {}", DisplayList(&self.moves));
debug!("collect_moves: {}", DisplayList(&self.moves));
}
}
@@ -1024,7 +1024,7 @@ impl Solver {
if let Some((rc, reg)) = m.from_reg() {
avail.free(rc, reg);
}
dbg!("move #{}: {}", i, m);
debug!("move #{}: {}", i, m);
i += 1;
continue;
}
@@ -1058,7 +1058,7 @@ impl Solver {
let m = self.moves[i].clone();
let toprc = m.rc().toprc();
if let Some(reg) = avail.iter(toprc).next() {
dbg!(
debug!(
"breaking cycle at {} with available {} register {}",
m,
toprc,
@@ -1089,7 +1089,7 @@ impl Solver {
// a last resort.
let slot = num_spill_slots;
num_spill_slots += 1;
dbg!("breaking cycle at {} with slot {}", m, slot);
debug!("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(),

View File

@@ -90,7 +90,7 @@ impl Spilling {
tracker: &mut LiveValueTracker,
) {
let _tt = timing::ra_spilling();
dbg!("Spilling for:\n{}", func.display(isa));
debug!("Spilling for:\n{}", func.display(isa));
let reginfo = isa.register_info();
let usable_regs = isa.allocatable_registers(func);
let mut ctx = Context {
@@ -118,7 +118,7 @@ impl<'a> Context<'a> {
}
fn visit_ebb(&mut self, ebb: Ebb, tracker: &mut LiveValueTracker) {
dbg!("Spilling {}:", ebb);
debug!("Spilling {}:", ebb);
self.cur.goto_top(ebb);
self.visit_ebb_header(ebb, tracker);
tracker.drop_dead_params();
@@ -198,14 +198,12 @@ 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) {
dbg!("Need {} reg for EBB param {}", rc, lv.value);
debug!("Need {} reg for EBB param {}", rc, lv.value);
match self.spill_candidate(mask, liveins) {
Some(cand) => {
dbg!(
debug!(
"Spilling live-in {} to make room for {} EBB param {}",
cand,
rc,
lv.value
cand, rc, lv.value
);
self.spill_reg(cand);
}
@@ -213,7 +211,7 @@ impl<'a> Context<'a> {
// We can't spill any of the live-in registers, so we have to spill an
// EBB argument. Since the current spill metric would consider all the
// EBB arguments equal, just spill the present register.
dbg!("Spilling {} EBB argument {}", rc, lv.value);
debug!("Spilling {} EBB argument {}", rc, lv.value);
// Since `spill_reg` will free a register, add the current one here.
self.pressure.take(rc);
@@ -237,7 +235,7 @@ impl<'a> Context<'a> {
constraints: &RecipeConstraints,
tracker: &mut LiveValueTracker,
) {
dbg!("Inst {}, {}", self.cur.display_inst(inst), self.pressure);
debug!("Inst {}, {}", self.cur.display_inst(inst), self.pressure);
debug_assert_eq!(self.cur.current_inst(), Some(inst));
debug_assert_eq!(self.cur.current_ebb(), Some(ebb));
@@ -279,7 +277,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) {
dbg!("Need {} reg from {} throughs", op.regclass, throughs.len());
debug!("Need {} reg from {} throughs", op.regclass, throughs.len());
match self.spill_candidate(mask, throughs) {
Some(cand) => self.spill_reg(cand),
None => panic!(
@@ -333,7 +331,7 @@ impl<'a> Context<'a> {
// Only collect the interesting register uses.
if reguse.fixed || reguse.tied || reguse.spilled {
dbg!(" reguse: {}", reguse);
debug!(" reguse: {}", reguse);
self.reg_uses.push(reguse);
}
}
@@ -406,7 +404,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) {
dbg!("Copy of {} reg causes spill", rc);
debug!("Copy of {} reg causes spill", rc);
// Spill a live register that is *not* used by the current instruction.
// Spilling a use wouldn't help.
//
@@ -489,7 +487,7 @@ impl<'a> Context<'a> {
let rc = self.reginfo.rc(rci);
self.pressure.free(rc);
self.spills.push(value);
dbg!("Spilled {}:{} -> {}", value, rc, self.pressure);
debug!("Spilled {}:{} -> {}", value, rc, self.pressure);
} else {
panic!("Cannot spill {} that was already on the stack", value);
}

View File

@@ -179,7 +179,7 @@ mod details {
/// This function is called by the publicly exposed pass functions.
pub(super) fn start_pass(pass: Pass) -> TimingToken {
let prev = CURRENT_PASS.with(|p| p.replace(pass));
dbg!("timing: Starting {}, (during {})", pass, prev);
debug!("timing: Starting {}, (during {})", pass, prev);
TimingToken {
start: Instant::now(),
pass,
@@ -191,7 +191,7 @@ mod details {
impl Drop for TimingToken {
fn drop(&mut self) {
let duration = self.start.elapsed();
dbg!("timing: Ending {}", self.pass);
debug!("timing: Ending {}", self.pass);
let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev));
debug_assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order");
PASS_TIME.with(|rc| {

View File

@@ -24,14 +24,14 @@ pub fn eliminate_unreachable_code(
continue;
}
dbg!("Eliminating unreachable {}", ebb);
debug!("Eliminating unreachable {}", ebb);
// Move the cursor out of the way and make sure the next lop iteration goes to the right
// EBB.
pos.prev_ebb();
// Remove all instructions from `ebb`.
while let Some(inst) = pos.func.layout.first_inst(ebb) {
dbg!(" - {}", pos.func.dfg.display_inst(inst, None));
debug!(" - {}", pos.func.dfg.display_inst(inst, None));
pos.func.layout.remove_inst(inst);
}

View File

@@ -11,5 +11,7 @@ publish = false
[dependencies]
cranelift-codegen = { path = "../codegen", version = "0.18.1" }
cranelift-reader = { path = "../reader", version = "0.18.1" }
file-per-thread-logger = "0.1.1"
filecheck = "0.3.0"
num_cpus = "1.8.0"
log = "0.4.3"

View File

@@ -3,7 +3,9 @@
//! This module provides the `ConcurrentRunner` struct which uses a pool of threads to run tests
//! concurrently.
use cranelift_codegen::dbg::LOG_FILENAME_PREFIX;
use cranelift_codegen::timing;
use file_per_thread_logger;
use num_cpus;
use std::panic::catch_unwind;
use std::path::{Path, PathBuf};
@@ -100,6 +102,7 @@ fn heartbeat_thread(replies: Sender<Reply>) -> thread::JoinHandle<()> {
thread::Builder::new()
.name("heartbeat".to_string())
.spawn(move || {
file_per_thread_logger::initialize(LOG_FILENAME_PREFIX);
while replies.send(Reply::Tick).is_ok() {
thread::sleep(Duration::from_secs(1));
}
@@ -116,6 +119,7 @@ fn worker_thread(
thread::Builder::new()
.name(format!("worker #{}", thread_num))
.spawn(move || {
file_per_thread_logger::initialize(LOG_FILENAME_PREFIX);
loop {
// Lock the mutex only long enough to extract a request.
let Request(jobid, path) = match requests.lock().unwrap().recv() {
@@ -140,7 +144,7 @@ fn worker_thread(
});
if let Err(ref msg) = result {
dbg!("FAIL: {}", msg);
error!("FAIL: {}", msg);
}
replies.send(Reply::Done { jobid, result }).unwrap();

View File

@@ -18,11 +18,13 @@
)
)]
#[macro_use(dbg)]
extern crate cranelift_codegen;
extern crate file_per_thread_logger;
extern crate cranelift_reader;
extern crate filecheck;
extern crate num_cpus;
#[macro_use]
extern crate log;
use cranelift_reader::TestCommand;
use runner::TestRunner;

View File

@@ -29,7 +29,7 @@ fn read_to_string<P: AsRef<Path>>(path: P) -> io::Result<String> {
/// If running this test causes a panic, it will propagate as normal.
pub fn run(path: &Path) -> TestResult {
let _tt = timing::process_file();
dbg!("---\nFile: {}", path.to_string_lossy());
info!("---\nFile: {}", path.to_string_lossy());
let started = time::Instant::now();
let buffer = read_to_string(path).map_err(|e| e.to_string())?;
let testfile = parse_test(&buffer).map_err(|e| e.to_string())?;
@@ -122,7 +122,7 @@ fn run_one_test<'a>(
) -> SubtestResult<()> {
let (test, flags, isa) = tuple;
let name = format!("{}({})", test.name(), func.name);
dbg!("Test: {} {}", name, isa.map_or("-", TargetIsa::name));
info!("Test: {} {}", name, isa.map_or("-", TargetIsa::name));
context.flags = flags;
context.isa = isa;

View File

@@ -41,7 +41,7 @@ impl SubTest for TestCompile {
.compile(isa)
.map_err(|e| pretty_error(&comp_ctx.func, context.isa, e))?;
dbg!(
info!(
"Generated {} bytes of code:\n{}",
code_size,
comp_ctx.func.display(isa)

View File

@@ -13,6 +13,7 @@ cranelift-codegen = { path = "../codegen", version = "0.18.1", default-features
cranelift-entity = { path = "../entity", version = "0.18.1", default-features = false }
hashmap_core = { version = "0.1.9", optional = true }
failure = "0.1.1"
log = { version = "0.4.3", default-features = false, features = ["release_max_level_warn"] }
[features]
default = ["std"]

View File

@@ -20,12 +20,13 @@
#[cfg_attr(test, macro_use)]
extern crate alloc;
#[macro_use]
extern crate cranelift_codegen;
#[macro_use]
extern crate cranelift_entity;
#[macro_use]
extern crate failure;
#[macro_use]
extern crate log;
mod backend;
mod data_context;

View File

@@ -467,7 +467,7 @@ where
pub fn define_function(&mut self, func: FuncId, ctx: &mut Context) -> ModuleResult<()> {
let compiled = {
let code_size = ctx.compile(self.backend.isa()).map_err(|e| {
dbg!(
info!(
"defining function {}: {}",
func,
ctx.func.display(self.backend.isa())

View File

@@ -17,6 +17,7 @@ hashmap_core = { version = "0.1.9", optional = true }
failure = { version = "0.1.1", default-features = false, features = ["derive"] }
failure_derive = { version = "0.1.1", default-features = false }
target-lexicon = { version = "0.0.3", default-features = false }
log = { version = "0.4.3", default-features = false, features = ["release_max_level_warn"] }
[dev-dependencies]
wabt = "0.4"

View File

@@ -67,7 +67,7 @@ impl FuncTranslator {
environ: &mut FE,
) -> WasmResult<()> {
let _tt = timing::wasm_translate_function();
dbg!(
info!(
"translate({} bytes, {}{})",
reader.bytes_remaining(),
func.name,
@@ -265,7 +265,7 @@ mod tests {
trans
.translate(&BODY, &mut ctx.func, &mut runtime.func_env())
.unwrap();
dbg!("{}", ctx.func.display(None));
debug!("{}", ctx.func.display(None));
ctx.verify(runtime.func_env().flags()).unwrap();
}
@@ -296,7 +296,7 @@ mod tests {
trans
.translate(&BODY, &mut ctx.func, &mut runtime.func_env())
.unwrap();
dbg!("{}", ctx.func.display(None));
debug!("{}", ctx.func.display(None));
ctx.verify(runtime.func_env().flags()).unwrap();
}
@@ -335,7 +335,7 @@ mod tests {
trans
.translate(&BODY, &mut ctx.func, &mut runtime.func_env())
.unwrap();
dbg!("{}", ctx.func.display(None));
debug!("{}", ctx.func.display(None));
ctx.verify(runtime.func_env().flags()).unwrap();
}
}

View File

@@ -24,7 +24,6 @@
#![cfg_attr(not(feature = "std"), no_std)]
#![cfg_attr(not(feature = "std"), feature(alloc))]
#[macro_use(dbg)]
extern crate cranelift_codegen;
#[macro_use]
extern crate cranelift_entity;
@@ -36,6 +35,9 @@ extern crate failure;
#[macro_use]
extern crate failure_derive;
#[macro_use]
extern crate log;
mod code_translator;
mod environ;
mod func_translator;