Add a bunch of debug logging

Cargo.toml

@@ -14,7 +14,7 @@ build = "build.rs"
 
 [features]
 default = ["cli"]
-cli = ["structopt"]
+cli = ["structopt", "tracing-subscriber"]
 
 [dependencies]
 anyhow = "1.0.65"
@@ -26,6 +26,8 @@ nom = "7.0.0"
 object = "0.26.0"
 structopt = { version = "0.3.21", optional = true }
 thiserror = "1.0.30"
+tracing = "0.1.37"
+tracing-subscriber = { version = "0.3.16", features = ["env-filter"], optional = true }
 
 [dev-dependencies]
 assert_cmd = "2"

src/bin/cov.rs

@@ -3,6 +3,8 @@ use llvm_profparser::*;
 use std::fs;
 use std::path::PathBuf;
 use structopt::StructOpt;
+use tracing_subscriber::filter::EnvFilter;
+use tracing_subscriber::{Layer, Registry};
 
 #[derive(Clone, Debug, Eq, PartialEq, StructOpt)]
 pub struct Opts {
@@ -32,10 +34,16 @@ pub struct ShowCommand {
     /// order `source,dest`
     #[structopt(long = "path-equivalence")]
     path_remapping: Option<PathRemapping>,
+    /// Turn on debug logging
+    #[structopt(long)]
+    debug: bool,
 }
 
 impl ShowCommand {
     fn run(&self) -> Result<()> {
+        if self.debug {
+            let _ = enable_debug_logging();
+        }
         let instr_prof = if self.instr_profile.len() == 1 {
             parse(&self.instr_profile[0])?
         } else if self.instr_profile.len() > 1 {
@@ -69,6 +77,14 @@ impl ShowCommand {
     }
 }
 
+fn enable_debug_logging() -> anyhow::Result<()> {
+    let filter = EnvFilter::new("cov=debug,llvm_profparser=debug");
+    let fmt = tracing_subscriber::fmt::Layer::default();
+    let subscriber = filter.and_then(fmt).with_subscriber(Registry::default());
+    tracing::subscriber::set_global_default(subscriber)?;
+    Ok(())
+}
+
 fn main() -> Result<()> {
     let opts = Opts::from_args();
     match opts.cmd {

src/bin/profparser.rs

@@ -7,6 +7,8 @@ use std::cmp::Ordering;
 use std::collections::BinaryHeap;
 use std::path::PathBuf;
 use structopt::StructOpt;
+use tracing_subscriber::filter::EnvFilter;
+use tracing_subscriber::{Layer, Registry};
 
 #[derive(Clone, Debug, Eq, PartialEq, StructOpt)]
 pub enum Command {
@@ -125,6 +127,9 @@ pub struct OverlapCommand {
 pub struct Opts {
     #[structopt(subcommand)]
     cmd: Command,
+    /// Turn on debug logging
+    #[structopt(long)]
+    debug: bool,
 }
 
 fn try_parse_weighted(input: &str) -> Result<(u64, String), String> {
@@ -371,8 +376,19 @@ impl MergeCommand {
     }
 }
 
+fn enable_debug_logging() -> anyhow::Result<()> {
+    let filter = EnvFilter::new("profparser=debug,llvm_profparser=debug");
+    let fmt = tracing_subscriber::fmt::Layer::default();
+    let subscriber = filter.and_then(fmt).with_subscriber(Registry::default());
+    tracing::subscriber::set_global_default(subscriber)?;
+    Ok(())
+}
+
 fn main() -> Result<()> {
     let opts = Opts::from_args();
+    if opts.debug {
+        let _ = enable_debug_logging();
+    }
     match opts.cmd {
         Command::Show { show } => show.run(),
         Command::Merge { merge } => merge.run(),

src/coverage/coverage_mapping.rs

@@ -11,6 +11,7 @@ use std::error::Error;
 use std::fmt;
 use std::fs;
 use std::path::{Path, PathBuf};
+use tracing::debug;
 
 /// Stores the instrumentation profile and information from the coverage mapping sections in the
 /// object files in order to construct a coverage report. Inspired, from the LLVM implementation
@@ -72,22 +73,30 @@ pub fn read_object_file(object: &Path, version: u64) -> Result<CoverageMappingIn
             LlvmSection::CoverageFunctions,
         ))??;
 
+    debug!("Parsed covfun section: {:?}", cov_fun);
+
     let cov_map = object_file
         .section_by_name("__llvm_covmap")
         .or(object_file.section_by_name(".lcovmap"))
         .map(|x| parse_coverage_mapping(object_file.endianness(), &x, version))
         .ok_or(SectionReadError::MissingSection(LlvmSection::CoverageMap))??;
 
+    debug!("Parsed covmap section: {:?}", cov_map);
+
     let prof_counts = object_file
         .section_by_name("__llvm_prf_cnts")
         .or(object_file.section_by_name(".lprfc"))
         .and_then(|x| parse_profile_counters(object_file.endianness(), &x).ok());
 
+    debug!("Parsed prf_cnts: {:?}", prof_counts);
+
     let prof_data = object_file
         .section_by_name("__llvm_prf_data")
         .or(object_file.section_by_name(".lprfd"))
         .and_then(|x| parse_profile_data(object_file.endianness(), &x).ok());
 
+    debug!("Parsed prf_data section: {:?}", prof_data);
+
     Ok(CoverageMappingInfo {
         cov_map,
         cov_fun,

src/hash_table.rs

@@ -5,6 +5,7 @@ use nom::{
     number::complete::*,
 };
 use std::borrow::Cow;
+use tracing::debug;
 
 #[derive(Copy, Clone, Debug)]
 struct KeyDataLen {
@@ -129,8 +130,10 @@ impl HashTable {
         bucket_start: usize,
     ) -> ParseResult<'a, Self> {
         assert!(bucket_start > 0);
-        let (bytes, _num_buckets) = le_u64(&input[bucket_start..])?;
+        let (bytes, num_buckets) = le_u64(&input[bucket_start..])?;
+        debug!("Number of hashtable buckets: {}", num_buckets);
         let (_bytes, mut num_entries) = le_u64(bytes)?;
+        debug!("Number of entries: {}", num_entries);
         let mut payload = input;
         let mut result = Self::new();
         while num_entries > 0 {
@@ -148,12 +151,16 @@ impl HashTable {
         mut num_entries: u64,
     ) -> ParseResult<'a, u64> {
         let (bytes, num_items_in_bucket) = le_u16(input)?;
+        debug!("Number of items in bucket: {}", num_items_in_bucket);
         let mut remaining = bytes;
         for _i in 0..num_items_in_bucket {
             let (bytes, _hash) = le_u64(remaining)?;
+            debug!("Hash(?): {}", _hash);
             let (bytes, lens) = read_key_data_len(bytes)?;
             let (bytes, key) = read_key(bytes, lens.key_len as usize)?;
+            debug!("lengths: {:?} and key: {}", lens, key);
             let (bytes, (hash, value)) = read_value(version, bytes, lens.data_len as usize)?;
+            debug!("hash: {}, value: {:?}", hash, value);
             self.0.insert((hash, key.to_string()), value);
             assert!(num_entries > 0);
             num_entries -= 1;

src/instrumentation_profile/indexed_profile.rs

@@ -9,6 +9,7 @@ use nom::{
 use std::collections::HashMap;
 use std::convert::TryFrom;
 use std::io::Read;
+use tracing::debug;
 
 #[derive(Debug, Clone, Eq, PartialEq, Hash, Ord, PartialOrd)]
 pub struct IndexedInstrProf;
@@ -156,12 +157,15 @@ impl InstrProfReader for IndexedInstrProf {
 
     fn parse_bytes(mut input: &[u8]) -> ParseResult<InstrumentationProfile> {
         let (bytes, header) = Self::parse_header(input)?;
-        let (bytes, _summary) = parse_summary(bytes, &header, false)?;
-        let (bytes, _cs_summary) = if header.is_csir_prof() {
+        debug!("Parsed header: {:?}", header);
+        let (bytes, summary) = parse_summary(bytes, &header, false)?;
+        debug!("Summary: {:?}", summary);
+        let (bytes, cs_summary) = if header.is_csir_prof() {
             parse_summary(bytes, &header, true)?
         } else {
             (bytes, None)
         };
+        debug!("cs_summary: {:?}", cs_summary);
         let mut profile = InstrumentationProfile {
             version: Some(header.version),
             has_csir: header.is_csir_prof(),
@@ -176,6 +180,7 @@ impl InstrProfReader for IndexedInstrProf {
             table_start,
             header.hash_offset as usize - table_start,
         )?;
+        debug!("Function hash table: {:?}", table);
         input = bytes;
         for ((hash, name), v) in &table.0 {
             let name = name.to_string();
@@ -187,6 +192,7 @@ impl InstrProfReader for IndexedInstrProf {
                 hash: Some(*hash),
                 record: v.clone(),
             };
+            debug!("Parsed record {:?}", record);
             profile.records.push(record);
         }
         Ok((input, profile))

src/instrumentation_profile/raw_profile.rs

@@ -15,6 +15,7 @@ use nom::{InputIter, InputLength, Slice};
 use std::convert::TryInto;
 use std::fmt::{Debug, Display};
 use std::mem::size_of;
+use tracing::debug;
 
 #[derive(Debug, Clone, Copy, Eq, PartialEq, Hash, Ord, PartialOrd)]
 pub enum RawProfileError {
@@ -302,6 +303,7 @@ where
             let mut data_section = vec![];
             for _ in 0..header.data_len {
                 let (bytes, data) = ProfileData::<T>::parse(input, header.endianness)?;
+                debug!("Parsed data section {:?}", data);
                 data_section.push(data);
                 input = bytes;
             }
@@ -326,6 +328,7 @@ where
                     0
                 };
                 let (bytes, record) = Self::read_raw_counts(&header, data, counters_offset, input)?;
+                debug!("Read counter record {:?}", record);
                 total_offset +=
                     counters_offset + (record.counts.len() * header.counter_size()) as i64;
                 counters_delta -= data.len() as u64;
@@ -343,6 +346,7 @@ where
                 let (new_bytes, names) = parse_string_ref(input)?;
                 input = new_bytes;
                 for name in names.split(INSTR_PROF_NAME_SEP) {
+                    debug!("Symbol name parsed: {}", name);
                     symtab.add_func_name(name.to_string(), Some(header.endianness));
                 }
             }
@@ -359,6 +363,7 @@ where
                 } else {
                     None
                 };
+                debug!("Parsed record: {:?} {:?} {:?}", name, hash, record);
                 result
                     .records
                     .push(NamedInstrProfRecord { name, hash, record });
@@ -402,6 +407,7 @@ where
                 names_delta,
                 value_kind_last,
             };
+            debug!("Read header {:?}", result);
             Ok((bytes, result))
         } else {
             //Err(Err::Failure(Error::new(input, ErrorKind::IsNot)))