track un-labeled time per span

abstutil/src/io.rs

@@ -48,9 +48,23 @@ pub fn write_binary<T: Serialize>(path: &str, obj: &T) -> Result<(), Error> {
 
 pub fn read_binary<T: DeserializeOwned>(path: &str, timer: &mut Timer) -> Result<T, Error> {
     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 {

abstutil/src/time.rs

@@ -27,7 +27,7 @@ impl Progress {
     }
 
     // Returns when done
-    fn next(&mut self) -> Option<String> {
+    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<String>,
+    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
             }
         }
     }

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<DrawBuilding> = map
             .all_buildings()
             .iter()
-            .map(|b| DrawBuilding::new(b))
-            .collect();
+            .map(|b| {
+                timer.next();
+                DrawBuilding::new(b)
+            }).collect();
         let parcels: Vec<DrawParcel> = map
             .all_parcels()
             .iter()