From 40fad5bd8609ebc7407067c7c278b8fb0a5110d5 Mon Sep 17 00:00:00 2001 From: Ben Frederickson Date: Fri, 14 Sep 2018 21:16:14 -0700 Subject: [PATCH] Warn if we aren't sampling fast enough At high rates, it's quite possible that we won't be able to sample the python process fast enough. This could lead to inaccurate results, and also might lead to issues like https://github.com/benfred/py-spy/issues/33 . Fix by warning if we aren't keeping up in sampling. Also tweak the default sampling rate to be lower (200). While I can sample at around 10K samples a second on any machine I've tested this should help here too. --- src/console_viewer.rs | 25 ++++++++++++++++++++----- src/main.rs | 22 +++++++++++++++++++--- src/utils.rs | 6 ++++-- 3 files changed, 43 insertions(+), 10 deletions(-) diff --git a/src/console_viewer.rs b/src/console_viewer.rs index 55fd1355..6b08f118 100644 --- a/src/console_viewer.rs +++ b/src/console_viewer.rs @@ -129,6 +129,16 @@ impl ConsoleViewer { ($($arg:tt)*) => { print!($($arg)*); out!(); } } self.console_config.reset_cursor()?; + let mut header_lines = if options.usage { 18 } else { 8 }; + + if let Some(delay) = self.stats.last_delay { + let late_rate = self.stats.late_samples as f64 / self.stats.overall_samples as f64; + if late_rate > 0.10 && delay > std::time::Duration::from_secs(1) { + let msg = format!("{:.2?} behind in sampling, results may be inaccurate. Try reducing the sampling rate.", delay); + out!("{}", style(msg).red()); + header_lines += 1; + } + } // Display aggregate stats about the process out!("Collecting samples from '{}' (python v{})", style(&self.command).green(), &self.version); @@ -170,8 +180,6 @@ impl ConsoleViewer { style(" Function (filename)").reverse() }; - let header_lines = if options.usage { 18 } else { 8 }; - // If we aren't at least 50 characters wide, lets use two lines per entry // Otherwise, truncate the filename so that it doesn't wrap around to the next line let header_lines = if width > 50 { header_lines } else { header_lines + height as usize / 2 }; @@ -225,6 +233,11 @@ impl ConsoleViewer { self.stats.last_error = Some(format!("{}", err)); } + pub fn increment_late_sample(&mut self, delay: std::time::Duration) { + self.stats.late_samples += 1; + self.stats.last_delay = Some(delay); + } + pub fn should_refresh(&self) -> bool { // update faster if we only have a few samples, or if we changed options match self.stats.overall_samples { @@ -292,12 +305,14 @@ struct Stats { overall_samples: u64, elapsed: f64, errors: u64, + late_samples: u64, threads: u64, active: u64, gil: u64, function_counts: HashMap, line_counts: HashMap, - last_error: Option + last_error: Option, + last_delay: Option, } impl Options { @@ -309,9 +324,9 @@ impl Options { impl Stats { fn new() -> Stats { Stats{current_samples: 0, overall_samples: 0, elapsed: 0., - errors: 0, threads: 0, gil: 0, active: 0, + errors: 0, late_samples: 0, threads: 0, gil: 0, active: 0, line_counts: HashMap::new(), function_counts: HashMap::new(), - last_error: None} + last_error: None, last_delay: None} } pub fn reset_current(&mut self) { diff --git a/src/main.rs b/src/main.rs index d3450afd..79678623 100644 --- a/src/main.rs +++ b/src/main.rs @@ -93,7 +93,11 @@ fn sample_console(process: &PythonSpy, 1.0 / rate as f64)?; let mut exitted_count = 0; - for _ in utils::Timer::new(Duration::from_nanos(1_000_000_000 / rate)) { + for sleep in utils::Timer::new(Duration::from_nanos(1_000_000_000 / rate)) { + if let Err(elapsed) = sleep { + console.increment_late_sample(elapsed); + } + match process.get_stack_traces() { Ok(traces) => { console.increment(&traces)?; @@ -130,8 +134,20 @@ fn sample_flame(process: &PythonSpy, filename: &str, args: &clap::ArgMatches) -> let mut errors = 0; let mut samples = 0; let mut exitted_count = 0; + println!(); + + for sleep in utils::Timer::new(Duration::from_nanos(1_000_000_000 / rate)) { + if let Err(delay) = sleep { + if delay > Duration::from_secs(1) { + // TODO: once this available on crates.io https://github.com/mitsuhiko/indicatif/pull/41 + // go progress.println instead + let term = console::Term::stdout(); + term.move_cursor_up(2)?; + println!("{:.2?} behind in sampling, results may be inaccurate. Try reducing the sampling rate.", delay); + term.move_cursor_down(1)?; + } + } - for _ in utils::Timer::new(Duration::from_nanos(1_000_000_000 / rate)) { match process.get_stack_traces() { Ok(traces) => { flame.increment(&traces)?; @@ -198,7 +214,7 @@ fn pyspy_main() -> Result<(), Error> { .long("rate") .value_name("rate") .help("The number of samples to collect per second") - .default_value("1000") + .default_value("200") .takes_value(true)) .arg(Arg::with_name("duration") .short("d") diff --git a/src/utils.rs b/src/utils.rs index 279d507e..df75b638 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -86,7 +86,7 @@ impl Timer { } impl Iterator for Timer { - type Item = (); + type Item = Result; fn next(&mut self) -> Option { self.samples += 1; @@ -94,8 +94,10 @@ impl Iterator for Timer { let desired = self.rate * self.samples; if desired > elapsed { std::thread::sleep(desired - elapsed); + Some(Ok(desired - elapsed)) + } else { + Some(Err(elapsed - desired)) } - Some(()) } }