diff --git a/src/commands/bench.rs b/src/commands/bench.rs index 31cf2b9..8e04d2d 100644 --- a/src/commands/bench.rs +++ b/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()); } } diff --git a/src/commands/serve.rs b/src/commands/serve.rs index c9e41e6..cadb261 100644 --- a/src/commands/serve.rs +++ b/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, + 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 = { + 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, }) } } diff --git a/src/main.rs b/src/main.rs index 09af87e..6e60a05 100644 --- a/src/main.rs +++ b/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::*; diff --git a/src/timer.rs b/src/timer.rs new file mode 100644 index 0000000..9563810 --- /dev/null +++ b/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, +} + +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); + } +}