Create debug output for execution time per stage and not found sounds

created debug output for sounds not found on exporting stage
and for execution time for each stage

openage/convert/processor/export/media_exporter.py

@@ -80,6 +80,8 @@ def export(
                 info("-- Exporting graphics files...")
 
             elif media_type is MediaType.SOUNDS:
+                kwargs["loglevel"] = args.debug_info
+                kwargs["debugdir"] = args.debugdir
                 export_func = MediaExporter._export_sound
                 info("-- Exporting sound files...")
 
@@ -284,6 +286,7 @@ def _export_sound(
         export_request: MediaExportRequest,
         sourcedir: Path,
         exportdir: Path,
+        **kwargs
     ) -> None:
         """
         Convert and export a sound file.
@@ -307,7 +310,7 @@ def _export_sound(
                 media_file = infile.read()
 
         else:
-            # TODO: Filter files that do not exist out sooner
+            debug_info.debug_not_found_sounds(kwargs["debugdir"], kwargs["loglevel"], source_file.name)
             return
 
         from ...service.export.opus.opusenc import encode

openage/convert/service/debug_info.py

@@ -32,6 +32,7 @@
     from openage.convert.value_object.init.game_version import GameVersion
     from openage.util.fslike.directory import Directory
 
+from io import TextIOWrapper
 
 def debug_cli_args(debugdir: Directory, loglevel: int, args: Namespace) -> None:
     """
@@ -677,3 +678,34 @@ def debug_media_cache(
 
     with logfile.open("w") as log:
         log.write(logtext)
+
+
+def debug_execution_time(debugdir: Directory, loglevel: int, stages_time: dict[str, float]) -> None:
+    """
+    Create debug output for execution time for each stage
+
+    :param debugdir: Output directory for the debug info.
+    :type debugdir: Directory
+    :param loglevel: Determines how detailed the output is.
+    :type loglevel: int
+    :param stages_time: Dict with execution time for each stage.
+    :type stages_time: dict
+    """
+    if loglevel < 1:
+        return
+
+    logfile = debugdir["execution_time"]
+    logtext = "".join(f"{k}: {v}\n" for k, v in stages_time.items())
+
+    with logfile.open("w") as log:
+        log.write(logtext)
+
+
+def debug_not_found_sounds(debugdir: Directory, loglevel: int, sound_name: str) -> None:
+    if loglevel < 6:
+        return
+
+    logfile = debugdir.joinpath("export/")["not_found_sounds"]
+
+    with logfile.open("a") as log:
+        log.write(sound_name+"\n")

openage/convert/tool/driver.py

@@ -8,13 +8,14 @@
 """
 from __future__ import annotations
 import typing
+import timeit
 
 
 from ...log import info, dbg
 from ..processor.export.modpack_exporter import ModpackExporter
 from ..service.debug_info import debug_gamedata_format
 from ..service.debug_info import debug_string_resources, \
-    debug_registered_graphics, debug_modpack
+    debug_registered_graphics, debug_modpack, debug_execution_time
 from ..service.init.changelog import (ASSET_VERSION)
 from ..service.read.gamedata import get_gamespec
 from ..service.read.palette import get_palettes
@@ -46,6 +47,8 @@ def convert_metadata(args: Namespace) -> None:
     """
     Converts the metadata part.
     """
+    execution_time: dict[str, float]
+
     if not args.flag("no_metadata"):
         info("converting metadata")
         # data_formatter = DataFormatter()
@@ -64,7 +67,7 @@ def convert_metadata(args: Namespace) -> None:
     gamedata_path = args.targetdir.joinpath('gamedata')
     if gamedata_path.exists():
         gamedata_path.removerecursive()
-
+    read_start = timeit.default_timer()
     # Read .dat
     debug_gamedata_format(args.debugdir, args.debug_info, args.game_version)
     gamespec = get_gamespec(args.srcdir, args.game_version, not args.flag("no_pickle_cache"))
@@ -84,16 +87,31 @@ def convert_metadata(args: Namespace) -> None:
     existing_graphics = get_existing_graphics(args)
     debug_registered_graphics(args.debugdir, args.debug_info, existing_graphics)
 
+    read_end = timeit.default_timer()
+
+    conversion_start = timeit.default_timer()
     # Convert
     modpacks = args.converter.convert(gamespec,
                                       args,
                                       string_resources,
                                       existing_graphics)
 
+    conversion_end = timeit.default_timer()
+
+    export_start = timeit.default_timer()
     for modpack in modpacks:
         ModpackExporter.export(modpack, args)
         debug_modpack(args.debugdir, args.debug_info, modpack)
 
+    export_end = timeit.default_timer()
+
+    stages_time = {
+        "read": read_end - read_start,
+        "convert": conversion_end - conversion_start,
+        "export": export_end - export_start,
+    }
+    debug_execution_time(args.debugdir, args.debug_info, stages_time)
+
     # TODO: player palettes
     # player_palette = PlayerColorTable(palette)
     # data_formatter.add_data(player_palette.dump("player_palette"))