[DWARF] Add logging to range building

cranelift/codegen/src/isa/x64/inst/regs.rs

@@ -263,6 +263,7 @@ pub fn show_ireg_sized(reg: Reg, size: u8) -> String {
     s
 }
 
+/// Pretty-print an x64 register.
 // N.B.: this is not an `impl PrettyPrint for Reg` because it is
 // specific to x64; other backends have analogous functions. The
 // disambiguation happens statically by virtue of higher-level,

cranelift/codegen/src/isa/x64/mod.rs

@@ -28,6 +28,7 @@ mod lower;
 mod pcc;
 pub mod settings;
 
+pub use inst::regs::pretty_print_reg;
 pub use inst::unwind::systemv::create_cie;
 
 /// An X64 backend.

crates/cranelift/src/debug/transform/debug_transform_logging.rs

@@ -1,10 +1,18 @@
-use crate::debug::Reader;
+use crate::{debug::Reader, translate::get_vmctx_value_label};
 use core::fmt;
+use cranelift_codegen::{ir::ValueLabel, isa::TargetIsa, LabelValueLoc, ValueLabelsRanges};
 use gimli::{
     write, AttributeValue, DebuggingInformationEntry, Dwarf, LittleEndian, Unit, UnitOffset,
     UnitSectionOffset,
 };
+use target_lexicon::Architecture;
 
+macro_rules! dbi_log_enabled {
+    () => {
+        cfg!(any(feature = "trace-log", debug_assertions))
+            && ::log::log_enabled!(target: "debug-info-transform", ::log::Level::Trace)
+    };
+}
 macro_rules! dbi_log {
     ($($tt:tt)*) => {
         if cfg!(any(feature = "trace-log", debug_assertions)) {
@@ -13,6 +21,7 @@ macro_rules! dbi_log {
     };
 }
 pub(crate) use dbi_log;
+pub(crate) use dbi_log_enabled;
 
 pub struct CompileUnitSummary<'a> {
     unit: &'a Unit<Reader<'a>, usize>,
@@ -274,3 +283,85 @@ fn get_offset_value(offset: UnitSectionOffset) -> usize {
         UnitSectionOffset::DebugTypesOffset(offs) => offs.0,
     }
 }
+
+pub fn log_get_value_name(value: ValueLabel) -> ValueNameSummary {
+    ValueNameSummary { value }
+}
+
+pub struct ValueNameSummary {
+    value: ValueLabel,
+}
+
+impl fmt::Debug for ValueNameSummary {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        if self.value == get_vmctx_value_label() {
+            f.pad("VMCTX")
+        } else {
+            f.pad(&format!("L#{}", self.value.as_u32()))
+        }
+    }
+}
+
+pub fn log_get_value_loc(loc: LabelValueLoc, isa: &dyn TargetIsa) -> ValueLocSummary {
+    ValueLocSummary { loc, isa }
+}
+
+pub struct ValueLocSummary<'a> {
+    loc: LabelValueLoc,
+    isa: &'a dyn TargetIsa,
+}
+
+impl<'a> fmt::Debug for ValueLocSummary<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        if let LabelValueLoc::Reg(reg) = self.loc {
+            // TODO-DebugInfo-Cleanup: ideally, 'pretty_print_reg' would be a method on ISA.
+            let reg_name = match self.isa.triple().architecture {
+                Architecture::X86_64 => cranelift_codegen::isa::x64::pretty_print_reg(reg, 8),
+                _ => String::new(),
+            };
+            if !reg_name.is_empty() {
+                return write!(f, "{reg_name}");
+            }
+        }
+
+        write!(f, "{:?}", self.loc)
+    }
+}
+
+pub fn log_get_value_ranges<'a>(
+    ranges: Option<&'a ValueLabelsRanges>,
+    isa: &'a dyn TargetIsa,
+) -> ValueRangesSummary<'a> {
+    ValueRangesSummary { ranges, isa }
+}
+
+pub struct ValueRangesSummary<'a> {
+    ranges: Option<&'a ValueLabelsRanges>,
+    isa: &'a dyn TargetIsa,
+}
+
+impl<'a> fmt::Debug for ValueRangesSummary<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        if let Some(ranges) = self.ranges {
+            // Sort the output first for nicer display.
+            let mut locals = Vec::new();
+            for value in ranges {
+                locals.push(*value.0);
+            }
+            locals.sort_by_key(|n| n.as_u32());
+
+            for i in 0..locals.len() {
+                let name = locals[i];
+                write!(f, "{:<6?}:", log_get_value_name(name))?;
+                for range in ranges.get(&name).unwrap() {
+                    write!(f, " {:?}", log_get_value_loc(range.loc, self.isa))?;
+                    write!(f, "@[{}..{})", range.start, range.end)?;
+                }
+                if i != locals.len() - 1 {
+                    writeln!(f)?;
+                }
+            }
+        }
+        Ok(())
+    }
+}

crates/cranelift/src/debug/transform/expression.rs

@@ -1,12 +1,18 @@
 use super::address_transform::AddressTransform;
+use super::dbi_log;
+use crate::debug::transform::debug_transform_logging::{
+    dbi_log_enabled, log_get_value_loc, log_get_value_name, log_get_value_ranges,
+};
 use crate::debug::ModuleMemoryOffset;
 use crate::translate::get_vmctx_value_label;
 use anyhow::{Context, Error, Result};
+use core::fmt;
 use cranelift_codegen::ir::ValueLabel;
 use cranelift_codegen::isa::TargetIsa;
 use cranelift_codegen::LabelValueLoc;
 use cranelift_codegen::ValueLabelsRanges;
 use gimli::{write, Expression, Operation, Reader, ReaderOffset};
+use itertools::Itertools;
 use std::cmp::PartialEq;
 use std::collections::{HashMap, HashSet};
 use std::hash::{Hash, Hasher};
@@ -296,7 +302,7 @@ impl CompiledExpression {
 
         // Some locals are present, preparing and divided ranges based on the scope
         // and frame_info data.
-        let mut ranges_builder = ValueLabelRangesBuilder::new(scope, addr_tr, frame_info);
+        let mut ranges_builder = ValueLabelRangesBuilder::new(scope, addr_tr, frame_info, isa);
         for p in self.parts.iter() {
             match p {
                 CompiledExpressionPart::Code(_)
@@ -651,7 +657,36 @@ struct CachedValueLabelRange {
     label_location: HashMap<ValueLabel, LabelValueLoc>,
 }
 
+struct BuiltRangeSummary<'a> {
+    range: &'a CachedValueLabelRange,
+    isa: &'a dyn TargetIsa,
+}
+
+impl<'a> fmt::Debug for BuiltRangeSummary<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        let range = self.range;
+        write!(f, "[")?;
+        let mut is_first = true;
+        for (value, value_loc) in &range.label_location {
+            if !is_first {
+                write!(f, ", ")?;
+            } else {
+                is_first = false;
+            }
+            write!(
+                f,
+                "{:?}:{:?}",
+                log_get_value_name(*value),
+                log_get_value_loc(*value_loc, self.isa)
+            )?;
+        }
+        write!(f, "]@[{}..{})", range.start, range.end)?;
+        Ok(())
+    }
+}
+
 struct ValueLabelRangesBuilder<'a, 'b> {
+    isa: &'a dyn TargetIsa,
     ranges: Vec<CachedValueLabelRange>,
     frame_info: Option<&'a FunctionFrameInfo<'b>>,
     processed_labels: HashSet<ValueLabel>,
@@ -662,6 +697,7 @@ impl<'a, 'b> ValueLabelRangesBuilder<'a, 'b> {
         scope: &[(u64, u64)], // wasm ranges
         addr_tr: &'a AddressTransform,
         frame_info: Option<&'a FunctionFrameInfo<'b>>,
+        isa: &'a dyn TargetIsa,
     ) -> Self {
         let mut ranges = Vec::new();
         for (wasm_start, wasm_end) in scope {
@@ -675,7 +711,17 @@ impl<'a, 'b> ValueLabelRangesBuilder<'a, 'b> {
             }
         }
         ranges.sort_unstable_by(|a, b| a.start.cmp(&b.start));
+
+        dbi_log!(
+            "Building ranges for values in scope: {}\n{:?}",
+            ranges
+                .iter()
+                .map(|r| format!("[{}..{})", r.start, r.end))
+                .join(" "),
+            log_get_value_ranges(frame_info.map(|f| f.value_ranges), isa)
+        );
         ValueLabelRangesBuilder {
+            isa,
             ranges,
             frame_info,
             processed_labels: HashSet::new(),
@@ -686,6 +732,7 @@ impl<'a, 'b> ValueLabelRangesBuilder<'a, 'b> {
         if self.processed_labels.contains(&label) {
             return;
         }
+        dbi_log!("Intersecting with {:?}", log_get_value_name(label));
         self.processed_labels.insert(label);
 
         let value_ranges = match self.frame_info.and_then(|fi| fi.value_ranges.get(&label)) {
@@ -750,9 +797,23 @@ impl<'a, 'b> ValueLabelRangesBuilder<'a, 'b> {
     pub fn into_ranges(self) -> impl Iterator<Item = CachedValueLabelRange> {
         // Ranges with not-enough labels are discarded.
         let processed_labels_len = self.processed_labels.len();
-        self.ranges
-            .into_iter()
-            .filter(move |r| r.label_location.len() == processed_labels_len)
+        let is_valid_range =
+            move |r: &CachedValueLabelRange| r.label_location.len() == processed_labels_len;
+
+        if dbi_log_enabled!() {
+            dbi_log!("Built ranges:");
+            for range in self.ranges.iter().filter(|r| is_valid_range(*r)) {
+                dbi_log!(
+                    "{:?}",
+                    BuiltRangeSummary {
+                        range,
+                        isa: self.isa
+                    }
+                );
+            }
+            dbi_log!("");
+        }
+        self.ranges.into_iter().filter(is_valid_range)
     }
 }
 
@@ -801,7 +862,9 @@ mod tests {
         FunctionFrameInfo, JumpTargetMarker, ValueLabel, ValueLabelsRanges,
     };
     use crate::CompiledFunctionMetadata;
+    use cranelift_codegen::{isa::lookup, settings::Flags};
     use gimli::{constants, Encoding, EndianSlice, Expression, RunTimeEndian};
+    use target_lexicon::triple;
     use wasmtime_environ::FilePos;
 
     macro_rules! dw_op {
@@ -1222,6 +1285,10 @@ mod tests {
         use super::ValueLabelRangesBuilder;
         use crate::debug::ModuleMemoryOffset;
 
+        let isa = lookup(triple!("x86_64"))
+            .expect("expect x86_64 ISA")
+            .finish(Flags::new(cranelift_codegen::settings::builder()))
+            .expect("Creating ISA");
         let addr_tr = create_mock_address_transform();
         let (value_ranges, value_labels) = create_mock_value_ranges();
         let fi = FunctionFrameInfo {
@@ -1230,15 +1297,16 @@ mod tests {
         };
 
         // No value labels, testing if entire function range coming through.
-        let builder = ValueLabelRangesBuilder::new(&[(10, 20)], &addr_tr, Some(&fi));
+        let builder = ValueLabelRangesBuilder::new(&[(10, 20)], &addr_tr, Some(&fi), isa.as_ref());
         let ranges = builder.into_ranges().collect::<Vec<_>>();
         assert_eq!(ranges.len(), 1);
         assert_eq!(ranges[0].func_index, 0);
         assert_eq!(ranges[0].start, 0);
         assert_eq!(ranges[0].end, 30);
 
         // Two labels ([email protected] and [email protected]), their common lifetime intersect at 5..25.
-        let mut builder = ValueLabelRangesBuilder::new(&[(10, 20)], &addr_tr, Some(&fi));
+        let mut builder =
+            ValueLabelRangesBuilder::new(&[(10, 20)], &addr_tr, Some(&fi), isa.as_ref());
         builder.process_label(value_labels.0);
         builder.process_label(value_labels.1);
         let ranges = builder.into_ranges().collect::<Vec<_>>();
@@ -1248,7 +1316,8 @@ mod tests {
 
         // Adds val2 with complex lifetime @0..10 and @20..30 to the previous test, and
         // also narrows range.
-        let mut builder = ValueLabelRangesBuilder::new(&[(11, 17)], &addr_tr, Some(&fi));
+        let mut builder =
+            ValueLabelRangesBuilder::new(&[(11, 17)], &addr_tr, Some(&fi), isa.as_ref());
         builder.process_label(value_labels.0);
         builder.process_label(value_labels.1);
         builder.process_label(value_labels.2);