Capstone 3: measure and speed it up

The index answers the queries of the previous lesson and nobody has asked how long it takes. This lesson asks, with the Instant of the performance lesson: it generates a folder big enough to see, times the build, times a thousand queries, and then changes one part at a time and measures again.

The rule of the whole lesson is that a faster version must return the same answer. A measurement of a function that computes something else is not an optimization, so every section prints the comparison next to the duration.

The corpus is generated by the program itself, which keeps the numbers reproducible: five hundred files of twenty lines with thirty thousand words each, every line holding one word of its own.

Time the build

The build reads every file, tokenizes it and fills the map. The program times only the build, so the file creation stays outside the measurement, and it prints the size of the result next to the duration: a build that got faster because it read fewer documents would otherwise look like a win.

The numbers below come from one run on the machine described at the end of the lesson and they move with the page cache. The first run after a reboot is slower than the third, which is why a measurement is repeated before it is believed.

use std::collections::{BTreeMap, BTreeSet}; use std::time::Instant; #[derive(Debug, Clone, Copy, PartialEq)] struct Hit { document: usize, line: usize, position: usize, } fn tokenize(text: &str) -> Vec<(usize, usize, String)> { let mut tokens = Vec::new(); for (line_number, line) in text.lines().enumerate() { let mut position = 0; for raw in line.split(|c: char| !c.is_alphanumeric()) { if raw.is_empty() { continue; } tokens.push((line_number + 1, position, raw.to_lowercase())); position += 1; } } tokens } struct Index { documents: Vec<String>, words: BTreeMap<String, Vec<Hit>>, } #[allow(dead_code)] impl Index { fn build(folder: &str) -> std::io::Result<Index> { let mut paths: Vec<std::path::PathBuf> = std::fs::read_dir(folder)? .filter_map(|entry| entry.ok()) .map(|entry| entry.path()) .filter(|path| path.extension().map(|extension| extension == "txt").unwrap_or(false)) .collect(); paths.sort(); let mut documents = Vec::new(); let mut words: BTreeMap<String, Vec<Hit>> = BTreeMap::new(); for path in paths { let text = std::fs::read_to_string(&path)?; let document = documents.len(); documents.push(path.file_name().unwrap().to_string_lossy().to_string()); for (line, position, word) in tokenize(&text) { words.entry(word).or_default().push(Hit { document, line, position }); } } Ok(Index { documents, words }) } fn hits(&self, word: &str) -> &[Hit] { self.words.get(word).map(|hits| hits.as_slice()).unwrap_or(&[]) } fn documents_with(&self, word: &str) -> Vec<usize> { let mut documents: Vec<usize> = self.hits(word).iter().map(|hit| hit.document).collect(); documents.dedup(); documents } fn query_or(&self, words: &[&str]) -> Vec<usize> { let mut result: Vec<usize> = Vec::new(); for word in words { for document in self.documents_with(word) { if !result.contains(&document) { result.push(document); } } } result.sort(); result } fn query_or_set(&self, words: &[&str]) -> Vec<usize> { let mut result: BTreeSet<usize> = BTreeSet::new(); for word in words { result.extend(self.documents_with(word)); } result.into_iter().collect() } } fn prepare(folder: &str, count: usize) -> std::io::Result<()> { std::fs::create_dir_all(folder)?; for document in 0..count { let mut text = String::new(); for line in 0..20 { text.push_str(&format!( "document {} line {} rust index search code\n", document, line )); } std::fs::write(format!("{folder}/doc{:03}.txt", document), text)?; } Ok(()) } fn main() { prepare("bench", 200).unwrap(); let start = Instant::now(); let index = Index::build("bench").unwrap(); let elapsed = start.elapsed(); println!("{} documents", index.documents.len()); println!("{} words", index.words.len()); println!("build took {} ms", elapsed.as_millis()); println!("{} hits for rust", index.hits("rust").len()); }

rm -rf bench
cargo run -q --release

200 documents
206 words
build took 74 ms
4000 hits for rust

Two hundred documents and four thousand hits for the word every line carries. The build is linear in the tokens and the map grows to two hundred and six words, which is the number that decides how much work a lookup does.

A release build is the one to measure: the debug profile of the profiles lesson keeps overflow checks and skips inlining, and a difference measured there says little about the program a user runs.

Time a thousand queries

One query is too fast to measure with a clock that reports milliseconds. The program runs a thousand of them and adds up the sizes of the answers, so the loop cannot be removed by the optimizer: the total is printed and a compiler that dropped the calls would print a different number.

The query is the union of four words, which is the expensive shape: each word contributes two hundred documents and the result contains all of them.

use std::collections::{BTreeMap, BTreeSet}; use std::time::Instant; #[derive(Debug, Clone, Copy, PartialEq)] struct Hit { document: usize, line: usize, position: usize, } fn tokenize(text: &str) -> Vec<(usize, usize, String)> { let mut tokens = Vec::new(); for (line_number, line) in text.lines().enumerate() { let mut position = 0; for raw in line.split(|c: char| !c.is_alphanumeric()) { if raw.is_empty() { continue; } tokens.push((line_number + 1, position, raw.to_lowercase())); position += 1; } } tokens } #[allow(dead_code)] struct Index { documents: Vec<String>, words: BTreeMap<String, Vec<Hit>>, } #[allow(dead_code)] impl Index { fn build(folder: &str) -> std::io::Result<Index> { let mut paths: Vec<std::path::PathBuf> = std::fs::read_dir(folder)? .filter_map(|entry| entry.ok()) .map(|entry| entry.path()) .filter(|path| path.extension().map(|extension| extension == "txt").unwrap_or(false)) .collect(); paths.sort(); let mut documents = Vec::new(); let mut words: BTreeMap<String, Vec<Hit>> = BTreeMap::new(); for path in paths { let text = std::fs::read_to_string(&path)?; let document = documents.len(); documents.push(path.file_name().unwrap().to_string_lossy().to_string()); for (line, position, word) in tokenize(&text) { words.entry(word).or_default().push(Hit { document, line, position }); } } Ok(Index { documents, words }) } fn hits(&self, word: &str) -> &[Hit] { self.words.get(word).map(|hits| hits.as_slice()).unwrap_or(&[]) } fn documents_with(&self, word: &str) -> Vec<usize> { let mut documents: Vec<usize> = self.hits(word).iter().map(|hit| hit.document).collect(); documents.dedup(); documents } fn query_or(&self, words: &[&str]) -> Vec<usize> { let mut result: Vec<usize> = Vec::new(); for word in words { for document in self.documents_with(word) { if !result.contains(&document) { result.push(document); } } } result.sort(); result } fn query_or_set(&self, words: &[&str]) -> Vec<usize> { let mut result: BTreeSet<usize> = BTreeSet::new(); for word in words { result.extend(self.documents_with(word)); } result.into_iter().collect() } } fn prepare(folder: &str, count: usize) -> std::io::Result<()> { std::fs::create_dir_all(folder)?; for document in 0..count { let mut text = String::new(); for line in 0..20 { text.push_str(&format!( "document {} line {} rust index search code\n", document, line )); } std::fs::write(format!("{folder}/doc{:03}.txt", document), text)?; } Ok(()) } fn main() { prepare("bench", 200).unwrap(); let index = Index::build("bench").unwrap(); let words = ["rust", "index", "search", "code"]; let start = Instant::now(); let mut total = 0; for _ in 0..1000 { total += index.query_or(&words).len(); } let elapsed = start.elapsed(); println!("1000 queries, {} results", total); println!("took {} ms", elapsed.as_millis()); }

rm -rf bench
cargo run -q --release

1000 queries, 200000 results
took 3543 ms

Three and a half seconds for a thousand queries is three and a half milliseconds each, and a single query looked instant. That is the reason to measure a loop rather than a call: the unit a user feels is the millisecond and the clock that resolves it is the loop.

The count of results is the guard against a measurement of nothing. A thousand queries that returned an empty vector would be fast and wrong, and the total in the first line is what makes the second line mean something. The lesson on cache and layout explains why four hundred thousand integers, built into a vector a thousand times, cost more than the bytes suggest.

The faster one must answer the same

The union of the previous section checks every document against a vector with contains, which is a linear search, so the whole union is quadratic in the number of documents. A BTreeSet does the same job in a sorted structure and drops the duplicates as it inserts them.

The program times both versions over the same thousand queries and prints the totals, the two durations and the comparison. The two totals are the proof that the faster version answers the same question.

use std::collections::{BTreeMap, BTreeSet}; use std::time::Instant; #[derive(Debug, Clone, Copy, PartialEq)] struct Hit { document: usize, line: usize, position: usize, } fn tokenize(text: &str) -> Vec<(usize, usize, String)> { let mut tokens = Vec::new(); for (line_number, line) in text.lines().enumerate() { let mut position = 0; for raw in line.split(|c: char| !c.is_alphanumeric()) { if raw.is_empty() { continue; } tokens.push((line_number + 1, position, raw.to_lowercase())); position += 1; } } tokens } #[allow(dead_code)] struct Index { documents: Vec<String>, words: BTreeMap<String, Vec<Hit>>, } #[allow(dead_code)] impl Index { fn build(folder: &str) -> std::io::Result<Index> { let mut paths: Vec<std::path::PathBuf> = std::fs::read_dir(folder)? .filter_map(|entry| entry.ok()) .map(|entry| entry.path()) .filter(|path| path.extension().map(|extension| extension == "txt").unwrap_or(false)) .collect(); paths.sort(); let mut documents = Vec::new(); let mut words: BTreeMap<String, Vec<Hit>> = BTreeMap::new(); for path in paths { let text = std::fs::read_to_string(&path)?; let document = documents.len(); documents.push(path.file_name().unwrap().to_string_lossy().to_string()); for (line, position, word) in tokenize(&text) { words.entry(word).or_default().push(Hit { document, line, position }); } } Ok(Index { documents, words }) } fn hits(&self, word: &str) -> &[Hit] { self.words.get(word).map(|hits| hits.as_slice()).unwrap_or(&[]) } fn documents_with(&self, word: &str) -> Vec<usize> { let mut documents: Vec<usize> = self.hits(word).iter().map(|hit| hit.document).collect(); documents.dedup(); documents } fn query_or(&self, words: &[&str]) -> Vec<usize> { let mut result: Vec<usize> = Vec::new(); for word in words { for document in self.documents_with(word) { if !result.contains(&document) { result.push(document); } } } result.sort(); result } fn query_or_set(&self, words: &[&str]) -> Vec<usize> { let mut result: BTreeSet<usize> = BTreeSet::new(); for word in words { result.extend(self.documents_with(word)); } result.into_iter().collect() } } fn prepare(folder: &str, count: usize) -> std::io::Result<()> { std::fs::create_dir_all(folder)?; for document in 0..count { let mut text = String::new(); for line in 0..20 { text.push_str(&format!( "document {} line {} rust index search code\n", document, line )); } std::fs::write(format!("{folder}/doc{:03}.txt", document), text)?; } Ok(()) } fn main() { prepare("bench", 200).unwrap(); let index = Index::build("bench").unwrap(); let words = ["rust", "index", "search", "code"]; let start = Instant::now(); let mut naive_total = 0; for _ in 0..1000 { naive_total += index.query_or(&words).len(); } let naive = start.elapsed(); let start = Instant::now(); let mut set_total = 0; for _ in 0..1000 { set_total += index.query_or_set(&words).len(); } let faster = start.elapsed(); println!("same answer: {}", naive_total == set_total); println!("vec {} ms, set {} ms", naive.as_millis(), faster.as_millis()); println!("faster: {}", faster < naive); }

rm -rf bench
cargo run -q --release

same answer: true
vec 5620 ms, set 2003 ms
faster: true

Two and a half times faster with the same two hundred thousand results, and the change is one line of data structure. The set also sorts the answer, which the vector version did with a separate call, so part of the gain is that the sort was already paid for by the tree.

The lesson on sets covers the structure, and the lesson on sorting covers the cost of the sort that the vector version paid at the end. A merge of two sorted document lists would be faster still, and it is the next step a real engine takes.

The ordered map and the hash map

The index uses a BTreeMap because the words come out in order, and an order costs a comparison per level of the tree. A HashMap looks a word up by its hash, which is constant, and pays for it with an order it does not keep.

To see the map instead of the disk, the program reads the tokens once and builds both maps from the same vector. It then looks up one word a hundred thousand times in each map, which is the operation a query repeats.

use std::collections::{BTreeMap, HashMap}; use std::time::Instant; #[derive(Debug, Clone, Copy, PartialEq)] struct Hit { document: usize, line: usize, position: usize, } fn tokenize(text: &str) -> Vec<(usize, usize, String)> { let mut tokens = Vec::new(); for (line_number, line) in text.lines().enumerate() { let mut position = 0; for raw in line.split(|c: char| !c.is_alphanumeric()) { if raw.is_empty() { continue; } tokens.push((line_number + 1, position, raw.to_lowercase())); position += 1; } } tokens } #[allow(dead_code)] fn prepare(folder: &str, count: usize) -> std::io::Result<Vec<String>> { std::fs::create_dir_all(folder)?; let mut paths = Vec::new(); for document in 0..count { let mut text = String::new(); for line in 0..20 { text.push_str(&format!( "document {} line {} word{} rust index search code\n", document, line, document * 20 + line )); } let path = format!("{folder}/doc{:03}.txt", document); std::fs::write(&path, text)?; paths.push(path); } paths.sort(); Ok(paths) } fn read_tokens(paths: &[String]) -> Vec<(usize, usize, usize, String)> { let mut tokens = Vec::new(); for (document, path) in paths.iter().enumerate() { let text = std::fs::read_to_string(path).unwrap(); for (line, position, word) in tokenize(&text) { tokens.push((document, line, position, word)); } } tokens } fn build_sorted(tokens: &[(usize, usize, usize, String)]) -> BTreeMap<String, Vec<Hit>> { let mut words: BTreeMap<String, Vec<Hit>> = BTreeMap::new(); for (document, line, position, word) in tokens { words.entry(word.clone()).or_default().push(Hit { document: *document, line: *line, position: *position, }); } words } fn build_hashed(tokens: &[(usize, usize, usize, String)]) -> HashMap<String, Vec<Hit>> { let mut words: HashMap<String, Vec<Hit>> = HashMap::new(); for (document, line, position, word) in tokens { words.entry(word.clone()).or_default().push(Hit { document: *document, line: *line, position: *position, }); } words } fn main() { let paths = prepare("bench", 500).unwrap(); let tokens = read_tokens(&paths); let start = Instant::now(); let sorted = build_sorted(&tokens); let sorted_build = start.elapsed(); let start = Instant::now(); let hashed = build_hashed(&tokens); let hashed_build = start.elapsed(); let start = Instant::now(); let mut sorted_found = 0; for _ in 0..100_000 { if sorted.contains_key("word7000") { sorted_found += 1; } } let sorted_lookup = start.elapsed(); let start = Instant::now(); let mut hashed_found = 0; for _ in 0..100_000 { if hashed.contains_key("word7000") { hashed_found += 1; } } let hashed_lookup = start.elapsed(); println!("same words: {}", sorted.len() == hashed.len()); println!("same answers: {}", sorted_found == hashed_found); println!("build: {} ms, {} ms", sorted_build.as_millis(), hashed_build.as_millis()); println!("100000 lookups: {} ms, {} ms", sorted_lookup.as_millis(), hashed_lookup.as_millis()); println!("hash faster: {}", hashed_lookup < sorted_lookup); }

rm -rf bench
cargo run -q --release

same words: true
same answers: true
build: 142 ms, 104 ms
 100000 lookups: 135 ms, 57 ms
hash faster: true

The two maps hold the same ten thousand words and answer the same, and the hash map is twice as fast on the lookups and a little faster on the build. The cost is the order: the hash map cannot print its words in order without a sort, which is why the index keeps the tree and why a program that prints the index pays for the tree once.

That is the shape of an optimization: a measurement, one change, another measurement, and the same answer on both sides. The lesson on HashMap and BTreeMap covers the two types in full. This is the end of the capstone, and the course index lists every part, and the Rust and C++ pages compare the language with the one this course is built to match.

Exercises

1. Sort the words of the hash map before printing and measure what the order costs.
2. Replace the union of sorted lists with a merge of the two hit vectors and compare three versions.
3. Repeat each measurement five times and print the best, as the performance lesson does.

The code on this page was built with cargo 1.96.1 and rustc 1.96.1 and run on Alpine Linux 3.24.3 (x86_64) in a Docker container.

Article author: Arthur Isaev