diff --git a/abstutil/src/io.rs b/abstutil/src/io.rs index f34efe5497..6722272a59 100644 --- a/abstutil/src/io.rs +++ b/abstutil/src/io.rs @@ -48,9 +48,23 @@ pub fn write_binary(path: &str, obj: &T) -> Result<(), Error> { pub fn read_binary(path: &str, timer: &mut Timer) -> Result { let reader = FileWithProgress::new(path)?; - timer.add_result(reader.get_timer_result()); + let total_bytes = reader.total_bytes; + + // Have to separately measure time here, since reader gets consumed. + let start = Instant::now(); let obj: T = serde_cbor::from_reader(reader).map_err(|err| Error::new(ErrorKind::Other, err))?; + let elapsed = elapsed_seconds(start); + timer.add_result( + elapsed, + format!( + "Reading {} ({} MB)... {}s", + path, + total_bytes / 1024 / 1024, + elapsed + ), + ); + Ok(obj) } @@ -195,15 +209,6 @@ impl FileWithProgress { last_printed_at: Instant::now(), }) } - - fn get_timer_result(&self) -> String { - format!( - "Reading {} ({} MB)... {}s", - self.path, - self.total_bytes / 1024 / 1024, - elapsed_seconds(self.started_at) - ) - } } impl Read for FileWithProgress { diff --git a/abstutil/src/time.rs b/abstutil/src/time.rs index 1ea2f18891..a49002c3db 100644 --- a/abstutil/src/time.rs +++ b/abstutil/src/time.rs @@ -27,7 +27,7 @@ impl Progress { } // Returns when done - fn next(&mut self) -> Option { + fn next(&mut self) -> Option<(f64, String)> { self.processed_items += 1; if self.processed_items > self.total_items { panic!( @@ -37,16 +37,14 @@ impl Progress { } if self.processed_items == self.total_items { + let elapsed = elapsed_seconds(self.started_at); let line = format!( "{}: {}/{}... {}s", - self.label, - self.processed_items, - self.total_items, - elapsed_seconds(self.started_at) + self.label, self.processed_items, self.total_items, elapsed ); // TODO blank till end of current line println!("\r{}", line); - return Some(line); + return Some((elapsed, line)); } else if elapsed_seconds(self.last_printed_at) >= PROGRESS_FREQUENCY_SECONDS { self.last_printed_at = Instant::now(); // TODO blank till end of current line @@ -78,6 +76,7 @@ struct TimerSpan { name: String, started_at: Instant, nested_results: Vec, + nested_time: f64, } impl Timer { @@ -103,6 +102,7 @@ impl Timer { name: name.to_string(), started_at: Instant::now(), nested_results: Vec::new(), + nested_time: 0.0, })); } @@ -115,14 +115,23 @@ impl Timer { ), }; assert_eq!(span.name, name); - let line = format!("{} took {}s", name, elapsed_seconds(span.started_at)); - println!("{}", line); + let elapsed = elapsed_seconds(span.started_at); + let line = format!("{} took {}s", name, elapsed); let padding = " ".repeat(self.stack.len()); match self.stack.last_mut() { Some(StackEntry::TimerSpan(ref mut s)) => { s.nested_results.push(format!("{}- {}", padding, line)); s.nested_results.extend(span.nested_results); + if span.nested_time != 0.0 { + println!("{}... plus {}s", name, elapsed - span.nested_time); + s.nested_results.push(format!( + " {}- ... plus {}s", + padding, + elapsed - span.nested_time + )); + } + s.nested_time += elapsed; } Some(StackEntry::Progress(p)) => panic!( "How is TimerSpan({}) nested under Progress({})?", @@ -131,8 +140,16 @@ impl Timer { None => { self.results.push(format!("{}- {}", padding, line)); self.results.extend(span.nested_results); + if span.nested_time != 0.0 { + println!("{}... plus {}s", name, elapsed - span.nested_time); + self.results + .push(format!(" - ... plus {}s", elapsed - span.nested_time)); + } + // Don't bother tracking excess time that the Timer has existed but had no spans } } + + println!("{}", line); } pub fn start_iter(&mut self, name: &str, total_items: usize) { @@ -157,23 +174,25 @@ impl Timer { } else { panic!("Can't next() while a TimerSpan is top of the stack"); }; - if let Some(result) = maybe_result { + if let Some((elapsed, result)) = maybe_result { self.stack.pop(); - self.add_result(result); + self.add_result(elapsed, result); } } - pub(crate) fn add_result(&mut self, line: String) { + pub(crate) fn add_result(&mut self, elapsed: f64, line: String) { let padding = " ".repeat(self.stack.len()); match self.stack.last_mut() { Some(StackEntry::TimerSpan(ref mut s)) => { s.nested_results.push(format!("{}- {}", padding, line)); + s.nested_time += elapsed; } Some(StackEntry::Progress(p)) => { panic!("How is something nested under Progress({})?", p.label) } None => { self.results.push(format!("{}- {}", padding, line)); + // Don't bother tracking excess time that the Timer has existed but had no spans } } } diff --git a/editor/src/render/map.rs b/editor/src/render/map.rs index bfb7700ff6..decb77a646 100644 --- a/editor/src/render/map.rs +++ b/editor/src/render/map.rs @@ -71,11 +71,14 @@ impl DrawMap { .iter() .map(|i| DrawIntersection::new(i, map, &lanes)) .collect(); + timer.start_iter("make DrawBuildings", map.all_buildings().len()); let buildings: Vec = map .all_buildings() .iter() - .map(|b| DrawBuilding::new(b)) - .collect(); + .map(|b| { + timer.next(); + DrawBuilding::new(b) + }).collect(); let parcels: Vec = map .all_parcels() .iter()