Add more tracing for turn processing.

Most of the time (1-2 seconds) is going to flight plan layout. There
don't seem to be any easy opportunities for improvement.

game/game.py

@@ -352,8 +352,10 @@ class Game:
 
     def pass_turn(self, no_action: bool = False) -> None:
         logging.info("Pass turn")
-        self.finish_turn(no_action)
-        self.initialize_turn()
+        with logged_duration("Turn finalization"):
+            self.finish_turn(no_action)
+        with logged_duration("Turn initialization"):
+            self.initialize_turn()
 
         # Autosave progress
         persistency.autosave(self)
@@ -399,22 +401,28 @@ class Game:
             return self.process_win_loss(turn_state)
 
         # Plan flights & combat for next turn
-        self.compute_conflicts_position()
-        self.compute_threat_zones()
-        self.compute_transit_networks()
+        with logged_duration("Computing conflict positions"):
+            self.compute_conflicts_position()
+        with logged_duration("Threat zone computation"):
+            self.compute_threat_zones()
+        with logged_duration("Transit network identification"):
+            self.compute_transit_networks()
         self.ground_planners = {}
 
         self.blue_procurement_requests.clear()
         self.red_procurement_requests.clear()
 
-        self.transfers.order_airlift_assets()
-        self.transfers.plan_transports()
+        with logged_duration("Procurement of airlift assets"):
+            self.transfers.order_airlift_assets()
+        with logged_duration("Transport planning"):
+            self.transfers.plan_transports()
 
-        with logged_duration("Mission planning"):
+        with logged_duration("Blue mission planning"):
             if self.settings.auto_ato_behavior is not AutoAtoBehavior.Disabled:
                 blue_planner = CoalitionMissionPlanner(self, is_player=True)
                 blue_planner.plan_missions()
 
+        with logged_duration("Red mission planning"):
             red_planner = CoalitionMissionPlanner(self, is_player=False)
             red_planner.plan_missions()
 

game/profiling.py

@@ -1,5 +1,8 @@
+from __future__ import annotations
+
 import logging
 import timeit
+from collections import defaultdict
 from contextlib import contextmanager
 from datetime import timedelta
 from typing import Iterator
@@ -11,3 +14,22 @@ def logged_duration(event: str) -> Iterator[None]:
     yield
     end = timeit.default_timer()
     logging.debug("%s took %s", event, timedelta(seconds=end - start))
+
+
+class MultiEventTracer:
+    def __init__(self) -> None:
+        self.events: dict[str, timedelta] = defaultdict(timedelta)
+
+    def __enter__(self) -> MultiEventTracer:
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb) -> None:
+        for event, duration in self.events.items():
+            logging.debug("%s took %s", event, duration)
+
+    @contextmanager
+    def trace(self, event: str) -> Iterator[None]:
+        start = timeit.default_timer()
+        yield
+        end = timeit.default_timer()
+        self.events[event] += timedelta(seconds=end - start)

gen/flights/ai_flight_planner.py

@@ -25,6 +25,7 @@ from dcs.unittype import FlyingType
 from game.factions.faction import Faction
 from game.infos.information import Information
 from game.procurement import AircraftProcurementRequest
+from game.profiling import logged_duration, MultiEventTracer
 from game.squadrons import AirWing, Squadron
 from game.theater import (
     Airfield,
@@ -807,13 +808,19 @@ class CoalitionMissionPlanner:
 
     def plan_missions(self) -> None:
         """Identifies and plans mission for the turn."""
-        for proposed_mission in self.propose_missions():
-            self.plan_mission(proposed_mission)
+        player = "Blue" if self.is_player else "Red"
+        with logged_duration(f"{player} mission identification and fulfillment"):
+            with MultiEventTracer() as tracer:
+                for proposed_mission in self.propose_missions():
+                    self.plan_mission(proposed_mission, tracer)
 
-        for critical_mission in self.critical_missions():
-            self.plan_mission(critical_mission, reserves=True)
+        with logged_duration(f"{player} reserve mission planning"):
+            with MultiEventTracer() as tracer:
+                for critical_mission in self.critical_missions():
+                    self.plan_mission(critical_mission, tracer, reserves=True)
 
-        self.stagger_missions()
+        with logged_duration(f"{player} mission scheduling"):
+            self.stagger_missions()
 
         for cp in self.objective_finder.friendly_control_points():
             inventory = self.game.aircraft_inventory.for_control_point(cp)
@@ -878,7 +885,9 @@ class CoalitionMissionPlanner:
                 threats[EscortType.Sead] = True
         return threats
 
-    def plan_mission(self, mission: ProposedMission, reserves: bool = False) -> None:
+    def plan_mission(
+        self, mission: ProposedMission, tracer: MultiEventTracer, reserves: bool = False
+    ) -> None:
         """Allocates aircraft for a proposed mission and adds it to the ATO."""
         builder = PackageBuilder(
             mission.location,
@@ -907,7 +916,10 @@ class CoalitionMissionPlanner:
                 # If the package does not need escorts they may be pruned.
                 escorts.append(proposed_flight)
                 continue
-            self.plan_flight(mission, proposed_flight, builder, missing_types, reserves)
+            with tracer.trace("Flight planning"):
+                self.plan_flight(
+                    mission, proposed_flight, builder, missing_types, reserves
+                )
 
         if missing_types:
             self.scrub_mission_missing_aircraft(
@@ -931,7 +943,8 @@ class CoalitionMissionPlanner:
             self.game, builder.package, self.is_player
         )
         for flight in builder.package.flights:
-            flight_plan_builder.populate_flight_plan(flight)
+            with tracer.trace("Flight plan population"):
+                flight_plan_builder.populate_flight_plan(flight)
 
         needed_escorts = self.check_needed_escorts(builder)
         for escort in escorts:
@@ -939,7 +952,8 @@ class CoalitionMissionPlanner:
             # impossible.
             assert escort.escort_type is not None
             if needed_escorts[escort.escort_type]:
-                self.plan_flight(mission, escort, builder, missing_types, reserves)
+                with tracer.trace("Flight planning"):
+                    self.plan_flight(mission, escort, builder, missing_types, reserves)
 
         # Check again for unavailable aircraft. If the escort was required and
         # none were found, scrub the mission.
@@ -959,7 +973,8 @@ class CoalitionMissionPlanner:
         # Add flight plans for escorts.
         for flight in package.flights:
             if not flight.flight_plan.waypoints:
-                flight_plan_builder.populate_flight_plan(flight)
+                with tracer.trace("Flight plan population"):
+                    flight_plan_builder.populate_flight_plan(flight)
 
         if package.has_players and self.game.settings.auto_ato_player_missions_asap:
             package.auto_asap = True