re add timer for `bench` and `serve`

src/commands/bench.rs

@@ -11,6 +11,7 @@ use tantivy::collector::TopCollector;
 use tantivy::collector::CountCollector;
 use clap::ArgMatches;
 use std::path::PathBuf;
+use timer::TimerTree;
 
 
 pub fn run_bench_cli(matches: &ArgMatches) -> Result<(), String> {
@@ -62,13 +63,17 @@ fn run_bench(index_path: &Path,
     for _ in 0..num_repeat {
         for query_txt in &queries {
             let query = query_parser.parse_query(&query_txt).unwrap();
+            // let num_terms = query.num_terms();
             let mut top_collector = TopCollector::with_limit(10);
             let mut count_collector = CountCollector::default();
+            let mut timing = TimerTree::default();
             {
+                let _search = timing.open("search");
                 let mut collector = chain().push(&mut top_collector).push(&mut count_collector);
                 query.search(&searcher, &mut collector)
                     .map_err(|e| format!("Failed while searching query {:?}.\n\n{:?}", query_txt, e))?;
             }
+            println!("{}\t{}\t{}", query_txt, count_collector.count(), timing.total_time());
         }
     }
     
@@ -81,6 +86,14 @@ fn run_bench(index_path: &Path,
             let mut top_collector = TopCollector::with_limit(10);
             query.search(&searcher, &mut top_collector)
                 .map_err(|e| format!("Failed while retrieving document for query {:?}.\n{:?}", query, e))?;
+            let mut timer = TimerTree::default();
+            {
+                let _scoped_timer_ = timer.open("total");
+                for doc_address in top_collector.docs() {
+                    searcher.doc(&doc_address).unwrap();
+                }
+            }
+            println!("{}\t{}", query_txt, timer.total_time());
         }
     }
     

src/commands/serve.rs

@@ -41,6 +41,7 @@ use tantivy::schema::NamedFieldDocument;
 use tantivy::schema::Schema;
 use tantivy::tokenizer::*;
 use tantivy::DocAddress;
+use timer::TimerTree;
 use urlencoded::UrlEncodedQuery;
 
 pub fn run_serve_cli(matches: &ArgMatches) -> Result<(), String> {
@@ -57,6 +58,7 @@ struct Serp {
     q: String,
     num_hits: usize,
     hits: Vec<Hit>,
+    timings: TimerTree,
 }
 
 #[derive(Serialize)]
@@ -119,13 +121,16 @@ impl IndexServer {
         let searcher = self.index.searcher();
         let mut count_collector = CountCollector::default();
         let mut top_collector = TopCollector::with_limit(num_hits);
+        let mut timer_tree = TimerTree::default();
         {
+            let _search_timer = timer_tree.open("search");
             let mut chained_collector = collector::chain()
                 .push(&mut top_collector)
                 .push(&mut count_collector);
             query.search(&searcher, &mut chained_collector)?;
         }
         let hits: Vec<Hit> = {
+            let _fetching_timer = timer_tree.open("fetching docs");
             top_collector.docs()
                 .iter()
                 .map(|doc_address| {
@@ -138,6 +143,7 @@ impl IndexServer {
             q,
             num_hits: count_collector.count(),
             hits,
+            timings: timer_tree,
         })
     }
 }

src/main.rs

@@ -23,6 +23,7 @@ extern crate serde_derive;
 
 use clap::{AppSettings, Arg, App, SubCommand};
 mod commands;
+pub mod timer;
 use self::commands::*;
 
 

src/timer.rs

@@ -0,0 +1,99 @@
+use time::PreciseTime;
+
+pub struct OpenTimer<'a> {
+    name: &'static str,
+    timer_tree: &'a mut TimerTree,
+    start: PreciseTime,
+    depth: u32,
+}
+
+impl<'a> OpenTimer<'a> {
+    /// Starts timing a new named subtask
+    ///
+    /// The timer is stopped automatically
+    /// when the `OpenTimer` is dropped.
+    pub fn open(&mut self, name: &'static str) -> OpenTimer {
+        OpenTimer {
+            name,
+            timer_tree: self.timer_tree,
+            start: PreciseTime::now(),
+            depth: self.depth + 1,
+        }
+    }
+}
+
+impl<'a> Drop for OpenTimer<'a> {
+    fn drop(&mut self) {
+        self.timer_tree.timings.push(Timing {
+            name: self.name,
+            duration: self.start
+                .to(PreciseTime::now())
+                .num_microseconds()
+                .unwrap(),
+            depth: self.depth,
+        });
+    }
+}
+
+/// Timing recording
+#[derive(Debug, Serialize)]
+pub struct Timing {
+    name: &'static str,
+    duration: i64,
+    depth: u32,
+}
+
+/// Timer tree
+#[derive(Debug, Serialize)]
+pub struct TimerTree {
+    timings: Vec<Timing>,
+}
+
+impl TimerTree {
+    /// Returns the total time elapsed in microseconds
+    pub fn total_time(&self) -> i64 {
+        self.timings.last().unwrap().duration
+    }
+
+    /// Open a new named subtask
+    pub fn open(&mut self, name: &'static str) -> OpenTimer {
+        OpenTimer {
+            name,
+            timer_tree: self,
+            start: PreciseTime::now(),
+            depth: 0,
+        }
+    }
+}
+
+impl Default for TimerTree {
+    fn default() -> TimerTree {
+        TimerTree {
+            timings: Vec::new(),
+        }
+    }
+}
+
+#[cfg(test)]
+mod tests {
+
+    use super::*;
+
+    #[test]
+    fn test_timer() {
+        let mut timer_tree = TimerTree::default();
+        {
+            let mut a = timer_tree.open("a");
+            {
+                let mut ab = a.open("b");
+                {
+                    let _abc = ab.open("c");
+                }
+                {
+                    let _abd = ab.open("d");
+                }
+            }
+        }
+        assert_eq!(timer_tree.timings.len(), 4);
+    }
+}