Skip to content

Commit

Permalink
Use log crate for debugging output in c2rust-analyze
Browse files Browse the repository at this point in the history 
Replace all eprintln! macros with uses of the
log crate for more efficient and fine-grained
debugging output.
  • Loading branch information
@ahomescu @thedataking
ahomescu authored and thedataking committed Nov 27, 2024
1 parent 68de84c commit 17b9044
Show file tree
Hide file tree
Showing 19 changed files with 149 additions and 139 deletions.
85 changes: 42 additions & 43 deletions c2rust-analyze/src/analyze.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,9 +25,9 @@ use crate::type_desc::Ownership;
use crate::util;
use crate::util::Callee;
use crate::util::TestAttr;
use ::log::warn;
use c2rust_pdg::graph::Graphs;
use c2rust_pdg::info::NodeInfo;
use log::{debug, info, warn};
use rustc_hir::def::DefKind;
use rustc_hir::def_id::CrateNum;
use rustc_hir::def_id::DefId;
Expand Down Expand Up @@ -244,15 +244,15 @@ fn update_pointer_info<'tcx>(acx: &mut AnalysisCtxt<'_, 'tcx>, mir: &Body<'tcx>)
_ => continue,
};

eprintln!(
debug!(
"update_pointer_info: visit assignment: {:?}[{}]: {:?}",
bb, i, stmt
);

if !pl.is_indirect() {
// This is a write directly to `pl.local`.
*write_count.entry(pl.local).or_insert(0) += 1;
eprintln!(" record write to LHS {:?}", pl);
debug!(" record write to LHS {:?}", pl);
}

let ref_pl = match *rv {
Expand All @@ -264,7 +264,7 @@ fn update_pointer_info<'tcx>(acx: &mut AnalysisCtxt<'_, 'tcx>, mir: &Body<'tcx>)
// For simplicity, we consider taking the address of a local to be a write. We
// expect this not to happen for the sorts of temporary refs we're looking for.
if !ref_pl.is_indirect() {
eprintln!(" record write to ref target {:?}", ref_pl);
debug!(" record write to ref target {:?}", ref_pl);
*write_count.entry(ref_pl.local).or_insert(0) += 1;
}

Expand Down Expand Up @@ -385,7 +385,7 @@ fn mark_foreign_fixed<'tcx>(
let fields = adt_def.all_fields();
for field in fields {
let field_lty = gacx.field_ltys[&field.did];
eprintln!(
debug!(
"adding FIXED permission for {adt_did:?} field {:?}",
field.did
);
Expand Down Expand Up @@ -573,9 +573,9 @@ struct FuncInfo<'tcx> {
}

fn run(tcx: TyCtxt) {
eprintln!("all defs:");
debug!("all defs:");
for ldid in tcx.hir_crate_items(()).definitions() {
eprintln!("{:?}", ldid);
debug!("{:?}", ldid);
}

// Load the list of fixed defs early, so any errors are reported immediately.
Expand All @@ -591,9 +591,9 @@ fn run(tcx: TyCtxt) {
// Follow a postorder traversal, so that callers are visited after their callees. This means
// callee signatures will usually be up to date when we visit the call site.
let all_fn_ldids = fn_body_owners_postorder(tcx);
eprintln!("callgraph traversal order:");
debug!("callgraph traversal order:");
for &ldid in &all_fn_ldids {
eprintln!(" {:?}", ldid);
debug!(" {:?}", ldid);
}

populate_field_users(&mut gacx, &all_fn_ldids);
Expand Down Expand Up @@ -629,9 +629,9 @@ fn run(tcx: TyCtxt) {

// Collect all `static` items.
let all_static_dids = all_static_items(tcx);
eprintln!("statics:");
debug!("statics:");
for &did in &all_static_dids {
eprintln!(" {:?}", did);
debug!(" {:?}", did);
}

// Assign global `PointerId`s for types of `static` items.
Expand Down Expand Up @@ -834,7 +834,7 @@ fn run(tcx: TyCtxt) {
// Remap pointers based on equivalence classes, so all members of an equivalence class now use
// the same `PointerId`.
let (global_counter, global_equiv_map) = global_equiv.renumber();
eprintln!("global_equiv_map = {global_equiv_map:?}");
debug!("global_equiv_map = {global_equiv_map:?}");
pointee_type::remap_pointers_global(
&mut global_pointee_types,
&global_equiv_map,
Expand All @@ -849,7 +849,7 @@ fn run(tcx: TyCtxt) {

let info = func_info.get_mut(&ldid).unwrap();
let (local_counter, local_equiv_map) = info.local_equiv.renumber(&global_equiv_map);
eprintln!("local_equiv_map = {local_equiv_map:?}");
debug!("local_equiv_map = {local_equiv_map:?}");
pointee_type::remap_pointers_local(
&mut global_pointee_types,
&mut info.local_pointee_types,
Expand Down Expand Up @@ -1043,8 +1043,8 @@ fn run(tcx: TyCtxt) {
&mut g_updates_forbidden,
);

eprintln!("=== ADT Metadata ===");
eprintln!("{:?}", gacx.adt_metadata);
debug!("=== ADT Metadata ===");
debug!("{:?}", gacx.adt_metadata);

let mut loop_count = 0;
loop {
Expand Down Expand Up @@ -1110,14 +1110,14 @@ fn run(tcx: TyCtxt) {
let added = new & !old;
let removed = old & !new;
let kept = old & new;
eprintln!(
debug!(
"changed {:?}: added {:?}, removed {:?}, kept {:?}",
ptr, added, removed, kept
);
num_changed += 1;
}
}
eprintln!(
debug!(
"iteration {}: {} global pointers changed",
loop_count, num_changed
);
Expand All @@ -1126,7 +1126,7 @@ fn run(tcx: TyCtxt) {
break;
}
}
eprintln!("reached fixpoint in {} iterations", loop_count);
info!("reached fixpoint in {} iterations", loop_count);

// Do final processing on each function.
for &ldid in &all_fn_ldids {
Expand Down Expand Up @@ -1404,7 +1404,7 @@ fn run2<'tcx>(
assert!(i < 100);
func_reports.clear();
all_rewrites.clear();
eprintln!("\n--- start rewriting ---");
info!("--- start rewriting ---");

// Update non-rewritten items first. This has two purposes. First, it clears the
// `new_keys()` lists, which we check at the end of the loop to see whether we've reached a
Expand Down Expand Up @@ -1536,7 +1536,7 @@ fn run2<'tcx>(
let mut adt_reports = HashMap::<DefId, String>::new();
for &def_id in gacx.adt_metadata.table.keys() {
if gacx.foreign_mentioned_tys.contains(&def_id) {
eprintln!("Avoiding rewrite for foreign-mentioned type: {def_id:?}");
debug!("Avoiding rewrite for foreign-mentioned type: {def_id:?}");
continue;
}
if fixed_defs.contains(&def_id) {
Expand Down Expand Up @@ -1587,7 +1587,7 @@ fn run2<'tcx>(

// Print labeling and rewrites for the current function.

eprintln!("\nfinal labeling for {:?}:", name);
debug!("\nfinal labeling for {:?}:", name);
let lcx1 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
let lcx2 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
for (local, decl) in mir.local_decls.iter_enumerated() {
Expand All @@ -1602,12 +1602,11 @@ fn run2<'tcx>(
);
}

eprintln!("\ntype assignment for {:?}:", name);
debug!("\ntype assignment for {:?}:", name);
rewrite::dump_rewritten_local_tys(&acx, &asn, pointee_types, &mir, describe_local);

eprintln!();
if let Some(report) = func_reports.remove(&ldid) {
eprintln!("{}", report);
debug!("{}", report);
}

info.acx_data.set(acx.into_data());
Expand Down Expand Up @@ -1673,7 +1672,7 @@ fn run2<'tcx>(
}

// Print results for `static` items.
eprintln!("\nfinal labeling for static items:");
debug!("\nfinal labeling for static items:");
let lcx1 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
let lcx2 = crate::labeled_ty::LabeledTyCtxt::new(tcx);
let mut static_dids = gacx.static_tys.keys().cloned().collect::<Vec<_>>();
Expand All @@ -1691,10 +1690,10 @@ fn run2<'tcx>(
&gasn.flags,
);
}
eprintln!("\n{statics_report}");
debug!("\n{statics_report}");

// Print results for ADTs and fields
eprintln!("\nfinal labeling for fields:");
debug!("\nfinal labeling for fields:");
let mut field_dids = gacx.field_ltys.keys().cloned().collect::<Vec<_>>();
field_dids.sort();
for did in field_dids {
Expand All @@ -1704,7 +1703,7 @@ fn run2<'tcx>(
if pid != PointerId::NONE {
let ty_perms = gasn.perms[pid];
let ty_flags = gasn.flags[pid];
eprintln!("{name:}: ({pid}) perms = {ty_perms:?}, flags = {ty_flags:?}");
debug!("{name:}: ({pid}) perms = {ty_perms:?}, flags = {ty_flags:?}");
}

// Emit annotations for fields
Expand Down Expand Up @@ -1739,7 +1738,7 @@ fn run2<'tcx>(
adt_dids.sort();
for did in adt_dids {
if let Some(report) = adt_reports.remove(&did) {
eprintln!("\n{}", report);
debug!("\n{}", report);
}
}

Expand Down Expand Up @@ -1778,17 +1777,17 @@ fn run2<'tcx>(
// ----------------------------------

// Report errors that were caught previously
eprintln!("\nerror details:");
debug!("\nerror details:");
for ldid in tcx.hir().body_owners() {
if let Some(detail) = gacx.fns_failed.get(&ldid.to_def_id()) {
if !detail.has_backtrace() {
continue;
}
eprintln!("\nerror in {:?}:\n{}", ldid, detail.to_string_full());
debug!("\nerror in {:?}:{}", ldid, detail.to_string_full());
}
}

eprintln!("\nerror summary:");
debug!("\nerror summary:");
fn sorted_def_ids(it: impl IntoIterator<Item = DefId>) -> Vec<DefId> {
let mut v = it.into_iter().collect::<Vec<_>>();
v.sort();
Expand All @@ -1802,27 +1801,27 @@ fn run2<'tcx>(
Some(detail) => detail.to_string_short(),
None => "(no panic)".into(),
};
eprintln!("analysis of {def_id:?} failed: {flags:?}, {detail_str}");
debug!("analysis of {def_id:?} failed: {flags:?}, {detail_str}");
}

for def_id in sorted_def_ids(gacx.dont_rewrite_statics.keys()) {
let flags = gacx.dont_rewrite_statics.get(def_id);
eprintln!("analysis of {def_id:?} failed: {flags:?}");
debug!("analysis of {def_id:?} failed: {flags:?}");
}

for def_id in sorted_def_ids(gacx.dont_rewrite_fields.keys()) {
let flags = gacx.dont_rewrite_fields.get(def_id);
eprintln!("analysis of {def_id:?} failed: {flags:?}");
debug!("analysis of {def_id:?} failed: {flags:?}");
}

eprintln!(
info!(
"\nsaw errors in {} / {} functions",
gacx.fns_failed.len(),
all_fn_ldids.len()
);

if !known_perm_error_fns.is_empty() {
eprintln!(
info!(
"saw permission errors in {} known fns",
known_perm_error_fns.len()
);
Expand Down Expand Up @@ -2184,7 +2183,7 @@ fn print_labeling_for_var<'tcx>(
perms[lty.label]
}
});
eprintln!("{}: addr_of = {:?}, type = {:?}", desc, addr_of1, ty1);
debug!("{}: addr_of = {:?}, type = {:?}", desc, addr_of1, ty1);

let addr_of2 = flags[addr_of_ptr];
let ty2 = lcx2.relabel(lty, &mut |lty| {
Expand All @@ -2194,14 +2193,14 @@ fn print_labeling_for_var<'tcx>(
flags[lty.label]
}
});
eprintln!(
debug!(
"{}: addr_of flags = {:?}, type flags = {:?}",
desc, addr_of2, ty2
);

let addr_of3 = addr_of_ptr;
let ty3 = lty;
eprintln!("{}: addr_of = {:?}, type = {:?}", desc, addr_of3, ty3);
debug!("{}: addr_of = {:?}, type = {:?}", desc, addr_of3, ty3);
}

fn print_function_pointee_types<'tcx>(
Expand All @@ -2210,9 +2209,9 @@ fn print_function_pointee_types<'tcx>(
mir: &Body<'tcx>,
pointee_types: PointerTable<PointeeTypes<'tcx>>,
) {
eprintln!("\npointee types for {}", name);
debug!("\npointee types for {}", name);
for (local, decl) in mir.local_decls.iter_enumerated() {
eprintln!(
debug!(
"{:?} ({}): addr_of = {:?}, type = {:?}",
local,
describe_local(acx.tcx(), decl),
Expand All @@ -2235,7 +2234,7 @@ fn print_function_pointee_types<'tcx>(
if tys.ltys.is_empty() && !tys.incomplete {
continue;
}
eprintln!(
debug!(
" pointer {:?}: {:?}{}",
ptr,
tys.ltys,
Expand Down
13 changes: 7 additions & 6 deletions c2rust-analyze/src/borrowck/def_use.rs
View file
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
use crate::borrowck::atoms::{AllFacts, AtomMaps, Loan, Path, SubPoint};
use log::debug;
use rustc_middle::mir::visit::{
MutatingUseContext, NonMutatingUseContext, NonUseContext, PlaceContext, Visitor,
};
Expand Down Expand Up @@ -96,7 +97,7 @@ struct DefUseVisitor<'tcx, 'a> {
impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {
fn visit_place(&mut self, place: &Place<'tcx>, context: PlaceContext, location: Location) {
self.super_place(place, context, location);
eprintln!(
debug!(
"visit place {:?} with context {:?} = {:?} at {:?}",
place,
context,
Expand Down Expand Up @@ -132,7 +133,7 @@ impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {
}

fn visit_local(&mut self, local: Local, context: PlaceContext, location: Location) {
eprintln!(
debug!(
"visit local {:?} with context {:?} = {:?} at {:?}",
local,
context,
Expand All @@ -157,7 +158,7 @@ impl<'tcx> Visitor<'tcx> for DefUseVisitor<'tcx, '_> {

fn visit_statement(&mut self, stmt: &Statement<'tcx>, location: Location) {
self.super_statement(stmt, location);
eprintln!("visit stmt {:?} at {:?}", stmt, location);
debug!("visit stmt {:?} at {:?}", stmt, location);

if let StatementKind::StorageDead(local) = stmt.kind {
// Observed: `StorageDead` emits `path_moved_at_base` at the `Mid` point.
Expand Down Expand Up @@ -194,7 +195,7 @@ impl<'tcx> LoanInvalidatedAtVisitor<'tcx, '_> {
context: PlaceContext,
location: Location,
) {
eprintln!(
debug!(
"access loan {:?} (kind {:?}) at location {:?} (context {:?} = {:?})",
loan,
borrow_kind,
Expand Down Expand Up @@ -223,7 +224,7 @@ impl<'tcx> LoanInvalidatedAtVisitor<'tcx, '_> {
impl<'tcx> Visitor<'tcx> for LoanInvalidatedAtVisitor<'tcx, '_> {
fn visit_place(&mut self, place: &Place<'tcx>, context: PlaceContext, location: Location) {
//self.super_place(place, context, location);
eprintln!(
debug!(
"loan_invalidated_at: visit place {:?} with context {:?} = {:?} at {:?}",
place,
context,
Expand Down Expand Up @@ -260,7 +261,7 @@ impl<'tcx> Visitor<'tcx> for LoanInvalidatedAtVisitor<'tcx, '_> {
}

fn visit_local(&mut self, local: Local, context: PlaceContext, location: Location) {
eprintln!(
debug!(
"loan_invalidated_at: visit local {:?} with context {:?} = {:?} at {:?}",
local,
context,
Expand Down
Loading

0 comments on commit 17b9044

Please sign in to comment.