Skip to content

Commit

Permalink
Move a lot of logging to log::info so that it's less spammy.
Browse files Browse the repository at this point in the history
The hidden logging can be enabled with the RUST_LOG=info env var.
  • Loading branch information
mstange committed May 5, 2024
1 parent dfc6f13 commit 97e67d7
Show file tree
Hide file tree
Showing 5 changed files with 86 additions and 15 deletions.
63 changes: 63 additions & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 2 additions & 0 deletions samply/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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]

Expand Down
2 changes: 2 additions & 0 deletions samply/src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -220,6 +220,8 @@ pub struct ProfileCreationArgs {
}

fn main() {
env_logger::init();

let opt = Opt::parse();
match opt.action {
Action::Load(load_args) => {
Expand Down
30 changes: 17 additions & 13 deletions samply/src/windows/etw_gecko.rs
Original file line number Diff line number Diff line change
Expand Up @@ -92,31 +92,33 @@ 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 {
reference_raw: e.EventHeader.TimeStamp as u64,
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));
}
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -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}");
}

}
Expand All @@ -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;
};

Expand Down Expand Up @@ -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
);
}
4 changes: 2 additions & 2 deletions samply/src/windows/profile_context.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down Expand Up @@ -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
Expand Down

0 comments on commit 97e67d7

Please sign in to comment.