From 97e67d79493288fe8038c684dec641a5e990dde3 Mon Sep 17 00:00:00 2001 From: Markus Stange Date: Sat, 4 May 2024 21:49:01 -0400 Subject: [PATCH] Move a lot of logging to log::info so that it's less spammy. The hidden logging can be enabled with the RUST_LOG=info env var. --- Cargo.lock | 63 +++++++++++++++++++++++++++ samply/Cargo.toml | 2 + samply/src/main.rs | 2 + samply/src/windows/etw_gecko.rs | 30 +++++++------ samply/src/windows/profile_context.rs | 4 +- 5 files changed, 86 insertions(+), 15 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 2b26f7ae..45e355a0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -39,6 +39,15 @@ dependencies = [ "zerocopy", ] +[[package]] +name = "aho-corasick" +version = "1.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8e60d3430d3a69478ad0993f19238d2df97c507009a52b3c10addcd7f6bcb916" +dependencies = [ + "memchr", +] + [[package]] name = "alloc-no-stdlib" version = "2.0.4" @@ -539,6 +548,29 @@ dependencies = [ "syn 2.0.58", ] +[[package]] +name = "env_filter" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a009aa4810eb158359dda09d0c87378e4bbb89b5a801f016885a4707ba24f7ea" +dependencies = [ + "log", + "regex", +] + +[[package]] +name = "env_logger" +version = "0.11.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "38b35839ba51819680ba087cd351788c9a3c476841207e0b8cee0b04722343b9" +dependencies = [ + "anstream", + "anstyle", + "env_filter", + "humantime", + "log", +] + [[package]] name = "equivalent" version = "1.0.1" @@ -911,6 +943,12 @@ version = "1.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9" +[[package]] +name = "humantime" +version = "2.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" + [[package]] name = "hyper" version = "1.3.1" @@ -1610,11 +1648,34 @@ dependencies = [ "syn 2.0.58", ] +[[package]] +name = "regex" +version = "1.10.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c117dbdfde9c8308975b6a18d71f3f385c89461f7b3fb054288ecf2a2058ba4c" +dependencies = [ + "aho-corasick", + "memchr", + "regex-automata", + "regex-syntax", +] + [[package]] name = "regex-automata" version = "0.4.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "86b83b8b9847f9bf95ef68afb0b8e6cdb80f498442f5179a29fad448fcc1eaea" +dependencies = [ + "aho-corasick", + "memchr", + "regex-syntax", +] + +[[package]] +name = "regex-syntax" +version = "0.8.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "adad44e29e4c806119491a7f06f03de4d1af22c3a680dd47f1e6e179439d1f56" [[package]] name = "reqwest" @@ -1785,6 +1846,7 @@ dependencies = [ "ctrlc", "debugid", "dirs", + "env_logger", "etw-reader", "flate2", "framehop", @@ -1797,6 +1859,7 @@ dependencies = [ "lazy_static", "libc", "linux-perf-data", + "log", "mach", "memchr", "memmap2", diff --git a/samply/Cargo.toml b/samply/Cargo.toml index b8bd0429..915988a4 100644 --- a/samply/Cargo.toml +++ b/samply/Cargo.toml @@ -46,6 +46,8 @@ once_cell = "1.17" fxhash = "0.2.1" mio = { version = "0.8.11", features = ["os-ext", "os-poll"] } ctrlc = "3.4.4" +log = "0.4.21" +env_logger = "0.11.3" [target.'cfg(any(target_os = "android", target_os = "macos", target_os = "linux"))'.dependencies] diff --git a/samply/src/main.rs b/samply/src/main.rs index 3fa08bc1..c7a243b5 100644 --- a/samply/src/main.rs +++ b/samply/src/main.rs @@ -220,6 +220,8 @@ pub struct ProfileCreationArgs { } fn main() { + env_logger::init(); + let opt = Opt::parse(); match opt.action { Action::Load(load_args) => { diff --git a/samply/src/windows/etw_gecko.rs b/samply/src/windows/etw_gecko.rs index cf4be0fb..89876782 100644 --- a/samply/src/windows/etw_gecko.rs +++ b/samply/src/windows/etw_gecko.rs @@ -92,14 +92,14 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) let perf_freq: u64 = parser.parse("PerfFreq"); let clock_type: u32 = parser.parse("ReservedFlags"); if clock_type != 1 { - println!("WARNING: QPC not used as clock"); + log::warn!("QPC not used as clock"); event_timestamps_are_qpc = false; } else { event_timestamps_are_qpc = true; } let events_lost: u32 = parser.parse("EventsLost"); if events_lost != 0 { - println!("WARNING: {} events lost", events_lost); + log::warn!("{} events lost", events_lost); } timestamp_converter = TimestampConverter { @@ -107,16 +107,18 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) raw_to_ns_factor: 1000 * 1000 * 1000 / perf_freq, }; - for i in 0..s.property_count() { - let property = s.property(i); - print_property(&mut parser, &property, false); + if log::log_enabled!(log::Level::Info) { + for i in 0..s.property_count() { + let property = s.property(i); + print_property(&mut parser, &property, false); + } } } "MSNT_SystemTrace/PerfInfo/CollectionStart" => { let interval_raw: u32 = parser.parse("NewInterval"); let interval_nanos = interval_raw as u64 * 100; let interval = SamplingInterval::from_nanos(interval_nanos); - println!("Sample rate {}ms", interval.as_secs_f64() * 1000.); + log::info!("Sample rate {}ms", interval.as_secs_f64() * 1000.); context.profile.borrow_mut().set_interval(interval); context.context_switch_handler.replace(ContextSwitchHandler::new(interval_raw as u64)); } @@ -227,7 +229,7 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) let mut thread = context.get_thread_mut(thread_id).unwrap(); if let Some(pending_stack ) = thread.pending_stacks.iter_mut().rev().find(|s| s.timestamp == timestamp_raw) { if let Some(kernel_stack) = pending_stack.kernel_stack.as_mut() { - eprintln!("Multiple kernel stacks for timestamp {timestamp_raw} on thread {thread_id}"); + log::warn!("Multiple kernel stacks for timestamp {timestamp_raw} on thread {thread_id}"); kernel_stack.extend(&stack); } else { pending_stack.kernel_stack = Some(stack); @@ -371,7 +373,7 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) let pdb_path: String = parser.try_parse("PdbFileName").unwrap(); //let pdb_path = Path::new(&pdb_path); let Some((ref path, image_size, timestamp)) = libs.remove(&(process_id, image_base)) else { - eprintln!("DbID_RSDS for image at 0x{:x} for pid {}, but has no entry in libs", image_base, process_id); + log::warn!("DbID_RSDS for image at 0x{:x} for pid {}, but has no entry in libs", image_base, process_id); return }; //eprintln!("DbgID_RSDS pid: {} 0x{:x} {} {} {} {}", process_id, image_base, path, debug_id, pdb_path, age); @@ -397,7 +399,7 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) } else if let Some(mut process) = context.get_process_mut(process_id) { process.pending_libraries.insert(image_base, info); } else { - eprintln!("No process for pid {process_id}"); + log::warn!("No process for pid {process_id}"); } } @@ -423,7 +425,7 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) } else if let Some(mut process) = context.get_process_mut(process_id) { process.pending_libraries.remove(&image_base) } else { - eprintln!("Received {} for unknown pid {process_id}", s.name()); + log::warn!("Received {} for unknown pid {process_id}", s.name()); return; }; @@ -810,12 +812,14 @@ pub fn profile_pid_from_etl_file(context: &mut ProfileContext, etl_file: &Path) for (_, thread) in threads.drain() { profile.add_thread(thread.builder); } }*/ - println!( + log::info!( "Took {} seconds", (Instant::now() - processing_start_timestamp).as_secs_f32() ); - println!( + log::info!( "{} events, {} samples, {} stack-samples", - event_count, sample_count, stack_sample_count + event_count, + sample_count, + stack_sample_count ); } diff --git a/samply/src/windows/profile_context.rs b/samply/src/windows/profile_context.rs index 72e5b01e..2da9f701 100644 --- a/samply/src/windows/profile_context.rs +++ b/samply/src/windows/profile_context.rs @@ -301,7 +301,7 @@ impl ProfileContext { pub fn add_thread(&mut self, pid: u32, tid: u32, start_time: Timestamp) { if !self.processes.contains_key(&pid) { - eprintln!("Adding thread {tid} for unknown pid {pid}"); + log::warn!("Adding thread {tid} for unknown pid {pid}"); return; } @@ -531,7 +531,7 @@ impl ProfileContext { fn add_kernel_drivers(&mut self) { for (path, start_avma, end_avma) in winutils::iter_kernel_drivers() { let path = self.map_device_path(&path); - eprintln!("kernel driver: {} {:x} {:x}", path, start_avma, end_avma); + log::info!("kernel driver: {} {:x} {:x}", path, start_avma, end_avma); let lib_info = self.get_library_info_for_path(&path); let lib_handle = self.profile.borrow_mut().add_lib(lib_info); self.profile