making a profiler to breakdown what parts of sim are slowest

abstutil/src/lib.rs

@@ -18,6 +18,6 @@ pub use crate::io::{
 pub use crate::logs::{format_log_record, LogAdapter};
 pub use crate::notes::note;
 pub use crate::random::{fork_rng, WeightedUsizeChoice};
-pub use crate::time::{elapsed_seconds, Timer};
+pub use crate::time::{elapsed_seconds, Profiler, Timer};
 
 const PROGRESS_FREQUENCY_SECONDS: f64 = 0.2;

abstutil/src/time.rs

@@ -1,4 +1,5 @@
 use crate::{notes, PROGRESS_FREQUENCY_SECONDS};
+use std::collections::HashMap;
 use std::io::{stdout, Write};
 use std::time::Instant;
 
@@ -218,3 +219,81 @@ impl Timer {
         }
     }
 }
+
+// For repeated things
+// TODO Why does the PartialEq derivation in sim require this?
+#[derive(Default)]
+pub struct Profiler {
+    entries: Vec<ProfilerEntry>,
+    current_entries: HashMap<String, Instant>,
+}
+
+struct ProfilerEntry {
+    name: String,
+    total_seconds: f64,
+    rounds: usize,
+}
+
+impl Profiler {
+    pub fn new() -> Profiler {
+        Profiler {
+            entries: Vec::new(),
+            current_entries: HashMap::new(),
+        }
+    }
+
+    // TODO Nested stuff winds up sorted before the parent
+    pub fn start(&mut self, name: &str) {
+        if self.current_entries.contains_key(name) {
+            panic!(
+                "Can't start profiling {}; it's already being recorded",
+                name
+            );
+        }
+        self.current_entries
+            .insert(name.to_string(), Instant::now());
+    }
+
+    pub fn stop(&mut self, name: &str) {
+        let start = self.current_entries.remove(name).expect(&format!(
+            "Can't stop profiling {}, because it was never started",
+            name
+        ));
+        let duration = elapsed_seconds(start);
+
+        if let Some(ref mut entry) = self.entries.iter_mut().find(|e| e.name == name) {
+            entry.total_seconds += duration;
+            entry.rounds += 1;
+        } else {
+            self.entries.push(ProfilerEntry {
+                name: name.to_string(),
+                total_seconds: duration,
+                rounds: 1,
+            });
+        }
+    }
+
+    pub fn dump(&self) {
+        if !self.current_entries.is_empty() {
+            panic!(
+                "Can't dump Profiler with active entries {:?}",
+                self.current_entries.keys()
+            );
+        }
+
+        println!("Profiler results so far:");
+        for entry in &self.entries {
+            // Suppress things that don't take any time.
+            let time_per_round = entry.total_seconds / (entry.rounds as f64);
+            if time_per_round < 0.0001 {
+                // TODO Actually, the granularity of the rounds might differ. Don't do this.
+                //continue;
+            }
+
+            println!(
+                "  - {}: {}s over {} rounds ({}s / round)",
+                entry.name, entry.total_seconds, entry.rounds, time_per_round,
+            );
+        }
+    }
+}

sim/src/driving.rs

@@ -10,7 +10,7 @@ use crate::{
     VehicleType, TIMESTEP,
 };
 use abstutil;
-use abstutil::{deserialize_btreemap, serialize_btreemap, Error};
+use abstutil::{deserialize_btreemap, serialize_btreemap, Error, Profiler};
 use geom::{Acceleration, Distance, Duration, Speed, EPSILON_DIST};
 use map_model::{
     BuildingID, IntersectionID, LaneID, Map, Path, PathStep, Position, Trace, Traversable, TurnID,
@@ -94,6 +94,7 @@ impl Car {
         // State transitions might be indicated
         transit_sim: &mut TransitSimState,
         intersections: &IntersectionSimState,
+        profiler: &mut Profiler,
     ) -> Result<Action, Error> {
         if self.parking.is_some() {
             // TODO right place for this check?
@@ -148,6 +149,7 @@ impl Car {
 
             // Don't exceed the speed limit
             {
+                profiler.start("    speed limit");
                 let current_speed_limit = vehicle.clamp_speed(current_on.speed_limit(map));
                 let accel =
                     vehicle.accel_to_achieve_speed_in_one_tick(self.speed, current_speed_limit);
@@ -158,9 +160,11 @@ impl Car {
                         self.id, accel, current_speed_limit
                     );
                 }
+                profiler.stop("    speed limit");
             }
 
             // Don't hit the vehicle in front of us
+            profiler.start("    follow vehicle");
             if let Some(other) = view.next_car_in_front_of(current_on, current_dist_along) {
                 assert!(self.id != other.id.as_car());
                 assert!(current_dist_along < other.dist_along);
@@ -193,8 +197,10 @@ impl Car {
                     debug!("  {} is {} behind {}'s back. Scanned ahead so far {} + lookahead dist {} + following dist {} = {} is less than that, so ignore them", self.id, dist_behind_others_back, other.id, dist_scanned_ahead, dist_to_lookahead, kinematics::FOLLOWING_DISTANCE, total_scanning_dist);
                 }
             }
+            profiler.stop("    follow vehicle");
 
             // Stop for something?
+            profiler.start("    stop early");
             if current_on.maybe_lane().is_some() {
                 let current_lane = current_on.as_lane();
                 let maybe_stop_early = current_router.stop_early_at_dist(
@@ -220,6 +226,7 @@ impl Car {
                     } else if current_router.should_vanish_at_border() {
                         // Don't limit acceleration, but also don't vanish before physically
                         // reaching the border.
+                        profiler.stop("    stop early");
                         break;
                     } else {
                         let req =
@@ -247,10 +254,12 @@ impl Car {
                         }
                         constraints.push((accel, Intent::StopAt(current_lane, dist_to_stop_at)));
                         // No use in further lookahead.
+                        profiler.stop("    stop early");
                         break;
                     }
                 }
             }
+            profiler.stop("    stop early");
 
             // Advance to the next step.
             let dist_this_step = current_on.length(map) - current_dist_along;
@@ -610,13 +619,17 @@ impl DrivingSimState {
         transit_sim: &mut TransitSimState,
         rng: &mut XorShiftRng,
         current_agent: &mut Option<AgentID>,
+        profiler: &mut Profiler,
     ) -> Result<(Vec<ParkedCar>, Vec<CarID>, Vec<(CarID, Position)>), Error> {
         // We don't need the queues at all during this function, so just move them to the view.
+        profiler.start("  populate driving view");
         std::mem::swap(&mut view.queues, &mut self.queues);
         self.populate_view(view);
+        profiler.stop("  populate driving view");
 
         // Could be concurrent, since this is deterministic -- EXCEPT for the rng, used to
         // sometimes pick a next lane to try for parking.
+        profiler.start("  react all cars");
         let mut requested_moves: Vec<(CarID, Action)> = Vec::new();
         for c in self.cars.values() {
             *current_agent = Some(AgentID::Car(c.id));
@@ -632,9 +645,11 @@ impl DrivingSimState {
                     parking_sim,
                     transit_sim,
                     intersections,
+                    profiler,
                 )?,
             ));
         }
+        profiler.stop("  react all cars");
 
         // In AORTA, there was a split here -- react vs step phase. We're still following the same
         // thing, but it might be slightly more clear to express it differently?
@@ -646,6 +661,7 @@ impl DrivingSimState {
 
         // Apply moves. Since lookahead behavior works, there are no conflicts to resolve, meaning
         // this could be applied concurrently!
+        profiler.start("  step all cars");
         for (id, act) in requested_moves {
             *current_agent = Some(AgentID::Car(id));
             match act {
@@ -706,8 +722,10 @@ impl DrivingSimState {
             }
         }
         *current_agent = None;
+        profiler.stop("  step all cars");
 
         // Group cars by lane and turn
+        profiler.start("  group cars into traversables");
         let mut cars_per_traversable = MultiMap::new();
         for c in self.cars.values() {
             // Also do some sanity checks.
@@ -719,12 +737,15 @@ impl DrivingSimState {
             }
             cars_per_traversable.insert(c.on, c.id);
         }
+        profiler.stop("  group cars into traversables");
 
         // Reset all queues -- only store ones with some agents present.
+        profiler.start("  recreate SimQueues");
         for (on, cars) in cars_per_traversable.into_iter() {
             self.queues
                 .insert(on, SimQueue::new(time, on, map, cars, &self.cars)?);
         }
+        profiler.stop("  recreate SimQueues");
 
         Ok((finished_parking, vanished_at_border, done_biking))
     }

sim/src/sim.rs

@@ -13,7 +13,7 @@ use crate::{
     AgentID, CarID, Event, ParkedCar, PedestrianID, SimStats, Tick, TripID, VehicleType, TIMESTEP,
 };
 use abstutil;
-use abstutil::Error;
+use abstutil::{Error, Profiler};
 use derivative::Derivative;
 use geom::{Distance, Pt2D};
 use map_model::{BuildingID, IntersectionID, LaneID, LaneType, Map, Path, Trace, Turn};
@@ -46,6 +46,10 @@ pub struct Sim {
     #[serde(skip_serializing, skip_deserializing)]
     stats: Option<SimStats>,
 
+    #[derivative(PartialEq = "ignore")]
+    #[serde(skip_serializing, skip_deserializing)]
+    pub profiler: Profiler,
+
     pub(crate) spawner: Spawner,
     scheduler: Scheduler,
     pub(crate) intersection_state: IntersectionSimState,
@@ -90,6 +94,7 @@ impl Sim {
             savestate_every,
             current_agent_for_debugging: None,
             stats: None,
+            profiler: Profiler::new(),
         }
     }
 
@@ -161,8 +166,11 @@ impl Sim {
         let mut view = WorldView::new();
         let mut events: Vec<Event> = Vec::new();
 
+        self.profiler.start("spawner step");
         self.spawner
             .step(self.time, map, &mut self.scheduler, &mut self.parking_state);
+        self.profiler.stop("spawner step");
+        self.profiler.start("scheduler step");
         self.scheduler.step(
             &mut events,
             self.time,
@@ -173,7 +181,9 @@ impl Sim {
             &self.intersection_state,
             &mut self.trips_state,
         );
+        self.profiler.stop("scheduler step");
 
+        self.profiler.start("driving step");
         let (newly_parked, at_border, done_biking) = self.driving_state.step(
             &mut view,
             &mut events,
@@ -184,7 +194,10 @@ impl Sim {
             &mut self.transit_state,
             &mut self.rng,
             &mut self.current_agent_for_debugging,
+            &mut self.profiler,
         )?;
+        self.profiler.stop("driving step");
+        self.profiler.start("handle driving step results");
         for p in newly_parked {
             events.push(Event::CarReachedParkingSpot(p.car, p.spot));
             capture_backtrace("CarReachedParkingSpot");
@@ -205,8 +218,12 @@ impl Sim {
             self.spawner
                 .bike_reached_end(self.time, bike, last_pos, map, &mut self.trips_state);
         }
+        self.profiler.stop("handle driving step results");
 
+        self.profiler.start("populate walking view");
         self.walking_state.populate_view(&mut view);
+        self.profiler.stop("populate walking view");
+        self.profiler.start("walking step");
         let (reached_parking, ready_to_bike) = self.walking_state.step(
             &mut events,
             TIMESTEP,
@@ -216,6 +233,8 @@ impl Sim {
             &mut self.trips_state,
             &mut self.current_agent_for_debugging,
         )?;
+        self.profiler.stop("walking step");
+        self.profiler.start("handle walking step results");
         for (ped, spot) in reached_parking {
             events.push(Event::PedReachedParkingSpot(ped, spot));
             capture_backtrace("PedReachedParkingSpot");
@@ -232,7 +251,9 @@ impl Sim {
             self.spawner
                 .ped_ready_to_bike(self.time, ped, sidewalk_pos, &mut self.trips_state);
         }
+        self.profiler.stop("handle walking step results");
 
+        self.profiler.start("transit step");
         self.transit_state.step(
             self.time,
             &mut events,
@@ -241,11 +262,14 @@ impl Sim {
             &mut self.spawner,
             map,
         );
+        self.profiler.stop("transit step");
 
         // Note that the intersection sees the WorldView BEFORE the updates that just happened this
         // tick.
+        self.profiler.start("intersection step");
         self.intersection_state
             .step(&mut events, self.time, map, &view);
+        self.profiler.stop("intersection step");
 
         // Do this at the end of the step, so that tick 0 actually occurs and things can happen
         // then.