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 #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

@@ -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<String, FunctionStatistics>,
     line_counts: HashMap<String, FunctionStatistics>,
-    last_error: Option<String>
+    last_error: Option<String>,
+    last_delay: Option<std::time::Duration>,
 }
 
 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) {

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")

src/utils.rs

@@ -86,16 +86,18 @@ impl Timer {
 }
 
 impl Iterator for Timer {
-    type Item = ();
+    type Item = Result<Duration, Duration>;
 
     fn next(&mut self) -> Option<Self::Item> {
         self.samples += 1;
         let elapsed = self.start.elapsed();
         let desired = self.rate * self.samples;
         if desired > elapsed {
             std::thread::sleep(desired - elapsed);
+            Some(Ok(desired - elapsed))
+        } else {
+            Some(Err(elapsed - desired))
         }
-        Some(())
     }
 }