Add logged_duration context manager for profiling.

game/profiling.py

@@ -0,0 +1,13 @@
+import logging
+import timeit
+from contextlib import contextmanager
+from datetime import timedelta
+from typing import Iterator
+
+
+@contextmanager
+def logged_duration(event: str) -> Iterator[None]:
+    start = timeit.default_timer()
+    yield
+    end = timeit.default_timer()
+    logging.debug("%s took %s", event, timedelta(seconds=end - start))

game/theater/conflicttheater.py

@@ -56,6 +56,7 @@ from .frontline import FrontLine
 from .landmap import Landmap, load_landmap, poly_contains
 from .projections import TransverseMercator
 from ..point_with_heading import PointWithHeading
+from ..profiling import logged_duration
 from ..utils import Distance, meters, nautical_miles
 
 SIZE_TINY = 150
@@ -114,7 +115,8 @@ class MizCampaignLoader:
     def __init__(self, miz: Path, theater: ConflictTheater) -> None:
         self.theater = theater
         self.mission = Mission()
-        self.mission.load_file(str(miz))
+        with logged_duration("Loading miz"):
+            self.mission.load_file(str(miz))
         self.control_point_id = itertools.count(1000)
 
         # If there are no red carriers there usually aren't red units. Make sure
@@ -682,7 +684,9 @@ class ConflictTheater:
             raise RuntimeError(
                 "Old format (non-miz) campaigns are no longer supported."
             )
-        MizCampaignLoader(directory / miz, t).populate_theater()
+
+        with logged_duration("Importing miz data"):
+            MizCampaignLoader(directory / miz, t).populate_theater()
         return t
 
     @property

game/theater/start_generator.py

@@ -46,6 +46,7 @@ from . import (
     Fob,
     OffMapSpawn,
 )
+from ..profiling import logged_duration
 from ..settings import Settings
 
 GroundObjectTemplates = Dict[str, Dict[str, Any]]
@@ -91,20 +92,21 @@ class GameGenerator:
         self.generator_settings = generator_settings
 
     def generate(self) -> Game:
-        # Reset name generator
+        with logged_duration("TGO population"):
-        namegen.reset()
+            # Reset name generator
-        self.prepare_theater()
+            namegen.reset()
-        game = Game(
+            self.prepare_theater()
-            player_name=self.player,
+            game = Game(
-            enemy_name=self.enemy,
+                player_name=self.player,
-            theater=self.theater,
+                enemy_name=self.enemy,
-            start_date=self.generator_settings.start_date,
+                theater=self.theater,
-            settings=self.settings,
+                start_date=self.generator_settings.start_date,
-            player_budget=self.generator_settings.player_budget,
+                settings=self.settings,
-            enemy_budget=self.generator_settings.enemy_budget,
+                player_budget=self.generator_settings.player_budget,
-        )
+                enemy_budget=self.generator_settings.enemy_budget,
+            )
 
-        GroundObjectGenerator(game, self.generator_settings).generate()
+            GroundObjectGenerator(game, self.generator_settings).generate()
         game.settings.version = VERSION
         game.begin_turn_0()
         return game

qt_ui/main.py

@@ -7,18 +7,18 @@ from pathlib import Path
 from typing import Optional
 
 import dcs
-from dcs.weapons_data import weapon_ids
-
 from PySide2 import QtWidgets
 from PySide2.QtGui import QPixmap
 from PySide2.QtWidgets import QApplication, QSplashScreen
+from dcs.weapons_data import weapon_ids
 
-from game import Game, db, persistency, VERSION
+from game import Game, VERSION, persistency
 from game.data.weapons import (
     WEAPON_FALLBACK_MAP,
     WEAPON_INTRODUCTION_YEARS,
     Weapon,
 )
+from game.profiling import logged_duration
 from game.settings import Settings
 from game.theater.start_generator import GameGenerator, GeneratorSettings
 from qt_ui import (
@@ -228,15 +228,16 @@ def main():
         lint_weapon_data()
 
     if args.subcommand == "new-game":
-        game = create_game(
+        with logged_duration("New game creation"):
-            args.campaign,
+            game = create_game(
-            args.blue,
+                args.campaign,
-            args.red,
+                args.blue,
-            args.supercarrier,
+                args.red,
-            args.auto_procurement,
+                args.supercarrier,
-            args.inverted,
+                args.auto_procurement,
-            args.cheats,
+                args.inverted,
-        )
+                args.cheats,
+            )
 
     run_ui(game)
 

qt_ui/widgets/QTopPanel.py

@@ -1,6 +1,3 @@
-import logging
-import timeit
-from datetime import timedelta
 from typing import List, Optional
 
 from PySide2.QtWidgets import (
@@ -15,10 +12,12 @@ from PySide2.QtWidgets import (
 import qt_ui.uiconstants as CONST
 from game import Game
 from game.event.airwar import AirWarEvent
+from game.profiling import logged_duration
 from gen.ato import Package
 from gen.flights.traveltime import TotEstimator
 from qt_ui.models import GameModel
 from qt_ui.widgets.QBudgetBox import QBudgetBox
+from qt_ui.widgets.QConditionsWidget import QConditionsWidget
 from qt_ui.widgets.QFactionsInfos import QFactionsInfos
 from qt_ui.widgets.QIntelBox import QIntelBox
 from qt_ui.widgets.clientslots import MaxPlayerCount
@@ -27,7 +26,6 @@ from qt_ui.windows.PendingTransfersDialog import PendingTransfersDialog
 from qt_ui.windows.QWaitingForMissionResultWindow import QWaitingForMissionResultWindow
 from qt_ui.windows.settings.QSettingsWindow import QSettingsWindow
 from qt_ui.windows.stats.QStatsWindow import QStatsWindow
-from qt_ui.widgets.QConditionsWidget import QConditionsWidget
 
 
 class QTopPanel(QFrame):
@@ -145,12 +143,10 @@ class QTopPanel(QFrame):
         self.dialog.show()
 
     def passTurn(self):
-        start = timeit.default_timer()
+        with logged_duration("Skipping turn"):
-        self.game.pass_turn(no_action=True)
+            self.game.pass_turn(no_action=True)
-        GameUpdateSignal.get_instance().updateGame(self.game)
+            GameUpdateSignal.get_instance().updateGame(self.game)
-        self.proceedButton.setEnabled(True)
+            self.proceedButton.setEnabled(True)
-        end = timeit.default_timer()
-        logging.info("Skipping turn took %s", timedelta(seconds=end - start))
 
     def negative_start_packages(self) -> List[Package]:
         packages = []

qt_ui/windows/QWaitingForMissionResultWindow.py

@@ -2,8 +2,6 @@ from __future__ import annotations
 
 import json
 import os
-import timeit
-from datetime import timedelta
 from typing import Sized
 
 from PySide2 import QtCore
@@ -25,6 +23,7 @@ from jinja2 import Environment, FileSystemLoader, select_autoescape
 from game.debriefing import Debriefing, wait_for_debriefing
 from game.game import Event, Game, logging
 from game.persistency import base_path
+from game.profiling import logged_duration
 from game.unitmap import UnitMap
 from qt_ui.windows.GameUpdateSignal import GameUpdateSignal
 
@@ -205,14 +204,12 @@ class QWaitingForMissionResultWindow(QDialog):
         )
 
     def process_debriefing(self):
-        start = timeit.default_timer()
+        with logged_duration("Turn processing"):
-        self.game.finish_event(event=self.gameEvent, debriefing=self.debriefing)
+            self.game.finish_event(event=self.gameEvent, debriefing=self.debriefing)
-        self.game.pass_turn()
+            self.game.pass_turn()
 
-        GameUpdateSignal.get_instance().sendDebriefing(self.debriefing)
+            GameUpdateSignal.get_instance().sendDebriefing(self.debriefing)
-        GameUpdateSignal.get_instance().updateGame(self.game)
+            GameUpdateSignal.get_instance().updateGame(self.game)
-        end = timeit.default_timer()
-        logging.info("Turn processing took %s", timedelta(seconds=end - start))
         self.close()
 
     def debriefing_directory_location(self) -> str: