Implement rudimentary progress reporter

A common complaint that I have heard (and have nyself) is that there is
little indication of what Korman is doing in the background. In PyPRP,
the raw export log was dumped to the console, and many liked to watch it
travel by as an indicator of progress. As such, I have implemented a
rudimentary progress monitor that outputs to the console into the export
logger.

Unfortunately, there is no "easy" way to show progress in the Blender UI
currently. Korman makes the assumption that nothing will touch
Blender's context while it is executing. Attempts to mvoe the exporter
into a background thread have all resulted in spectacular failures. So,
this will have to do for now.

korman/exporter/convert.py

@@ -43,9 +43,6 @@ class Exporter:
 
     def run(self):
         with logger.ExportLogger(self._op.filepath) as self.report:
-            self.report.msg("Exporting '{}.age'", self.age_name)
-            start = time.perf_counter()
-
             # Step 0: Init export resmgr and stuff
             self.mgr = manager.ExportManager(self)
             self.mesh = mesh.MeshConverter(self)
@@ -54,6 +51,18 @@ class Exporter:
             self.animation = animation.AnimationConverter(self)
             self.sumfile = sumfile.SumFile()
 
+            # Step 0.9: Init the progress mgr
+            self.report.progress_add_step("Collecting Objects")
+            self.report.progress_add_step("Harvesting Actors")
+            if self._op.bake_lighting:
+                etlight.LightBaker.add_progress_steps(self.report)
+            self.report.progress_add_step("Exporting Scene Objects")
+            self.report.progress_add_step("Exporting Logic Nodes")
+            self.report.progress_add_step("Finalizing Plasma Logic")
+            self.report.progress_add_step("Exporting Textures")
+            self.report.progress_add_step("Composing Geometry")
+            self.report.progress_start("EXPORTING AGE")
+
             # Step 1: Create the age info and the pages
             self._export_age_info()
 
@@ -90,17 +99,18 @@ class Exporter:
             # Step 5.1: Save out the export report.
             #           If the export fails and this doesn't save, we have bigger problems than
             #           these little warnings and notices.
+            self.report.progress_end()
             self.report.save()
 
-            # And finally we crow about how awesomely fast we are...
-            end = time.perf_counter()
-            self.report.msg("\nExported {}.age in {:.2f} seconds", self.age_name, end-start)
-
     def _bake_static_lighting(self):
         oven = etlight.LightBaker(self.report)
         oven.bake_static_lighting(self._objects)
 
     def _collect_objects(self):
+        self.report.progress_advance()
+        self.report.progress_range = len(bpy.data.objects)
+        inc_progress = self.report.progress_increment
+
         # Grab a naive listing of enabled pages
         age = bpy.context.scene.world.plasma_age
         pages_enabled = frozenset([page.name for page in age.pages if page.enabled])
@@ -135,6 +145,7 @@ class Exporter:
                     self._objects.append(obj)
                 elif page not in all_pages:
                     error.add(page, obj.name)
+            inc_progress()
         error.raise_if_error()
 
     def _export_age_info(self):
@@ -186,7 +197,11 @@ class Exporter:
         return so.coord.object
 
     def _export_scene_objects(self):
+        self.report.progress_advance()
+        self.report.progress_range = len(self._objects)
+        inc_progress = self.report.progress_increment
         log_msg = self.report.msg
+
         for bl_obj in self._objects:
             log_msg("\n[SceneObject '{}']".format(bl_obj.name))
 
@@ -213,6 +228,7 @@ class Exporter:
             for mod in bl_obj.plasma_modifiers.modifiers:
                 log_msg("Exporting '{}' modifier".format(mod.bl_label), indent=1)
                 mod.export(self, bl_obj, sceneobject)
+            inc_progress()
 
     def _export_empty_blobj(self, so, bo):
         # We don't need to do anything here. This function just makes sure we don't error out
@@ -230,18 +246,30 @@ class Exporter:
             self.report.msg("No material(s) on the ObData, so no drawables", indent=1)
 
     def _export_referenced_node_trees(self):
+        self.report.progress_advance()
+        self.report.progress_range = len(self.want_node_trees)
+        inc_progress = self.report.progress_increment
+
         self.report.msg("\nChecking Logic Trees...")
-        need_to_export = ((name, bo, so) for name, (bo, so) in self.want_node_trees.items()
-                                         if name not in self.node_trees_exported)
+        need_to_export = [(name, bo, so) for name, (bo, so) in self.want_node_trees.items()
+                                         if name not in self.node_trees_exported]
+        self.report.progress_value = len(self.want_node_trees) - len(need_to_export)
+
         for tree, bo, so in need_to_export:
             self.report.msg("NodeTree '{}'", tree, indent=1)
             bpy.data.node_groups[tree].export(self, bo, so)
+            inc_progress()
 
     def _harvest_actors(self):
+        self.report.progress_advance()
+        self.report.progress_range = len(self._objects) + len(bpy.data.textures)
+        inc_progress = self.report.progress_increment
+
         for bl_obj in self._objects:
             for mod in bl_obj.plasma_modifiers.modifiers:
                 if mod.enabled:
                     self.actors.update(mod.harvest_actors())
+            inc_progress()
 
         # This is a little hacky, but it's an edge case... I guess?
         # We MUST have CoordinateInterfaces for EnvironmentMaps (DCMs, bah)
@@ -251,6 +279,7 @@ class Exporter:
                 viewpt = envmap.viewpoint_object
                 if viewpt is not None:
                     self.actors.add(viewpt.name)
+            inc_progress()
 
     def has_coordiface(self, bo):
         if bo.type in {"CAMERA", "EMPTY", "LAMP"}:
@@ -269,6 +298,10 @@ class Exporter:
         return False
 
     def _post_process_scene_objects(self):
+        self.report.progress_advance()
+        self.report.progress_range = len(self._objects)
+        inc_progress = self.report.progress_increment
+
         mat_mgr = self.mesh.material
         for bl_obj in self._objects:
             sceneobject = self.mgr.find_object(plSceneObject, bl=bl_obj)
@@ -291,3 +324,4 @@ class Exporter:
                 proc = getattr(mod, "post_export", None)
                 if proc is not None:
                     proc(self, bl_obj, sceneobject)
+            inc_progress()

korman/exporter/etlight.py

@@ -27,9 +27,25 @@ class LightBaker:
 
     def __init__(self, report=None):
         self._lightgroups = {}
-        self._report = report if report is not None else ExportLogger()
+        if report is None:
+            self._report = ExportLogger()
+            self.add_progress_steps(self._report)
+            self._report.progress_start("PREVIEWING LIGHTING")
+            self._own_report = True
+        else:
+            self._report = report
+            self._own_report = False
         self._uvtexs = {}
 
+    def __del__(self):
+        if self._own_report:
+            self._report.progress_end()
+
+    @staticmethod
+    def add_progress_steps(report):
+        report.progress_add_step("Searching for Bahro")
+        report.progress_add_step("Baking Static Lighting")
+
     def _apply_render_settings(self, toggle, vcols):
         render = bpy.context.scene.render
         toggle.track(render, "use_textures", False)
@@ -79,11 +95,15 @@ class LightBaker:
             return result
 
     def _bake_static_lighting(self, bake, toggle):
+        inc_progress = self._report.progress_increment
+
         # Step 0.9: Make all layers visible.
         #           This prevents context operators from phailing.
         bpy.context.scene.layers = (True,) * _NUM_RENDER_LAYERS
 
         # Step 1: Prepare... Apply UVs, etc, etc, etc
+        self._report.progress_advance()
+        self._report.progress_range = len(bake)
         self._report.msg("Preparing to bake...", indent=1)
         for key in bake.keys():
             if key[0] == "lightmap":
@@ -103,21 +123,23 @@ class LightBaker:
                         bake[key].pop(i)
             else:
                 raise RuntimeError(key[0])
+            inc_progress()
         self._report.msg("    ...")
 
         # Step 2: BAKE!
+        self._report.progress_advance()
+        self._report.progress_range = len(bake)
         for key, value in bake.items():
-            if not value:
-                continue
-
-            if key[0] == "lightmap":
-                self._report.msg("{} Lightmap(s) [H:{:X}]", len(value), hash(key), indent=1)
-                self._bake_lightmaps(value, key[1:])
-            elif key[0] == "vcol":
-                self._report.msg("{} Crap Light(s)", len(value), indent=1)
-                self._bake_vcols(value)
-            else:
-                raise RuntimeError(key[0])
+            if value:
+                if key[0] == "lightmap":
+                    self._report.msg("{} Lightmap(s) [H:{:X}]", len(value), hash(key), indent=1)
+                    self._bake_lightmaps(value, key[1:])
+                elif key[0] == "vcol":
+                    self._report.msg("{} Crap Light(s)", len(value), indent=1)
+                    self._bake_vcols(value)
+                else:
+                    raise RuntimeError(key[0])
+            inc_progress()
 
         # Return how many thingos we baked
         return sum(map(len, bake.values()))

korman/exporter/logger.py

@@ -15,21 +15,30 @@
 
 from pathlib import Path
 import sys
+import time
+
+_HEADING_SIZE = 50
 
 class ExportLogger:
     def __init__(self, age_path=None):
         self._porting = []
         self._warnings = []
-        self._age_path = age_path
+        self._age_path = Path(age_path) if age_path is not None else None
         self._file = None
 
+        self._progress_steps = []
+        self._step_id = -1
+        self._step_max = 0
+        self._step_progress = 0
+        self._time_start_overall = 0
+        self._time_start_step = 0
+
     def __enter__(self):
         assert self._age_path is not None
 
         # Make the log file name from the age file path -- this ensures we're not trying to write
         # the log file to the same directory Blender.exe is in, which might be a permission error
-        my_path = Path(self._age_path)
-        my_path = my_path.with_name("{}_export".format(my_path.stem)).with_suffix(".log")
+        my_path = self._age_path.with_name("{}_export".format(self._age_path.stem)).with_suffix(".log")
         self._file = open(str(my_path), "w")
         return self
 
@@ -37,15 +46,101 @@ class ExportLogger:
         self._file.close()
         return False
 
+    def progress_add_step(self, name):
+        assert self._step_id == -1
+        self._progress_steps.append(name)
+
+    def progress_advance(self):
+        """Advances the progress bar to the next step"""
+        if self._step_id != -1:
+            self._progress_print_step(done=True)
+        assert self._step_id < len(self._progress_steps)
+
+        self._step_id += 1
+        self._step_max = 0
+        self._step_progress = 0
+        self._time_start_step = time.perf_counter()
+        self._progress_print_step()
+
+    def progress_complete_step(self):
+        """Manually completes the current step"""
+        assert self._step_id != -1
+        self._progress_print_step(done=True)
+
+    def progress_end(self):
+        self._progress_print_step(done=True)
+        assert self._step_id+1 == len(self._progress_steps)
+
+        export_time = time.perf_counter() - self._time_start_overall
+        if self._age_path is not None:
+            self.msg("\nExported '{}' in {:.2f}s", self._age_path.name, export_time)
+            print("\nEXPORTED '{}' IN {:.2f}s".format(self._age_path.name, export_time))
+        else:
+            print("\nCOMPLETED IN {:.2f}s".format(export_time))
+        self._progress_print_heading()
+        print()
+
+    def progress_increment(self):
+        """Increments the progress of the current step"""
+        assert self._step_id != -1
+        self._step_progress += 1
+        if self._step_max != 0:
+            self._progress_print_step()
+
+    def _progress_print_heading(self, text=None):
+        if text:
+            num_chars = len(text)
+            border = "-" * int((_HEADING_SIZE - (num_chars + 2)) / 2)
+            pad = " " if num_chars % 2 == 1 else ""
+            print(border, " ", pad, text, " ", border, sep="")
+        else:
+            print("-" * _HEADING_SIZE)
+
+    def _progress_print_step(self, done=False):
+        if done:
+            stage = "DONE IN {:.2f}s".format(time.perf_counter() - self._time_start_step)
+            end = "\n"
+        else:
+            if self._step_max != 0:
+                stage = "{} of {}".format(self._step_progress, self._step_max)
+            else:
+                stage = ""
+            end = "\r"
+        print("{}\t(step {}/{}): {}".format(self._progress_steps[self._step_id], self._step_id+1,
+                                            len(self._progress_steps), stage),
+              end=end)
+
+    def _progress_get_max(self):
+        return self._step_max
+    def _progress_set_max(self, value):
+        assert self._step_id != -1
+        self._step_max = value
+        self._progress_print_step()
+    progress_range = property(_progress_get_max, _progress_set_max)
+
+    def progress_start(self, action):
+        if self._age_path is not None:
+            self.msg("Exporting '{}'", self._age_path.name)
+        self._progress_print_heading("Korman")
+        self._progress_print_heading(action)
+        self._time_start_overall = time.perf_counter()
+
+    def _progress_get_current(self):
+        return self._step_progress
+    def _progress_set_current(self, value):
+        assert self._step_id != -1
+        self._step_progress = value
+        if self._step_max != 0:
+            self._progress_print_step()
+    progress_value = property(_progress_get_current, _progress_set_current)
+
     def msg(self, *args, **kwargs):
         assert args
-        indent = kwargs.get("indent", 0)
-        msg = "{}{}".format("    " * indent, args[0])
-        if len(args) > 1:
-            msg = msg.format(*args[1:], **kwargs)
-        if self._file is None:
-            print(msg)
-        else:
+        if self._file is not None:
+            indent = kwargs.get("indent", 0)
+            msg = "{}{}".format("    " * indent, args[0])
+            if len(args) > 1:
+                msg = msg.format(*args[1:], **kwargs)
             self._file.writelines((msg, "\n"))
 
     def port(self, *args, **kwargs):
@@ -54,9 +149,7 @@ class ExportLogger:
         msg = "{}PORTING: {}".format("    " * indent, args[0])
         if len(args) > 1:
             msg = msg.format(*args[1:], **kwargs)
-        if self._file is None:
-            print(msg)
-        else:
+        if self._file is not None:
             self._file.writelines((msg, "\n"))
         self._porting.append(args[0])
 
@@ -70,8 +163,6 @@ class ExportLogger:
         msg = "{}WARNING: {}".format("    " * indent, args[0])
         if len(args) > 1:
             msg = msg.format(*args[1:], **kwargs)
-        if self._file is None:
-            print(msg)
-        else:
+        if self._file is not None:
             self._file.writelines((msg, "\n"))
         self._warnings.append(args[0])

korman/exporter/material.py

@@ -618,6 +618,10 @@ class MaterialConverter:
             self._pending[key].append(layer.key)
 
     def finalize(self):
+        self._report.progress_advance()
+        self._report.progress_range = len(self._pending)
+        inc_progress = self._report.progress_increment
+
         for key, layers in self._pending.items():
             name = str(key)
             self._report.msg("\n[Mipmap '{}']", name)
@@ -683,6 +687,7 @@ class MaterialConverter:
                 else:
                     mipmap = pages[page]
                 layer.object.texture = mipmap.key
+            inc_progress()
 
     def get_materials(self, bo):
         return self._obj2mat.get(bo, [])

korman/exporter/mesh.py

@@ -174,11 +174,15 @@ class MeshConverter:
 
     def finalize(self):
         """Prepares all baked Plasma geometry to be flushed to the disk"""
+        self._report.progress_advance()
+        self._report.progress_range = len(self._dspans)
+        inc_progress = self._report.progress_increment
+        log_msg = self._report.msg
 
+        log_msg("\nFinalizing Geometry")
         for loc in self._dspans.values():
             for dspan in loc.values():
-                self._report.msg("\n[DrawableSpans '{}']", dspan.key.name)
-                self._report.msg("Composing geometry data", indent=1)
+                log_msg("[DrawableSpans '{}']", dspan.key.name, indent=1)
 
                 # This mega-function does a lot:
                 # 1. Converts SourceSpans (geospans) to Icicles and bakes geometry into plGBuffers
@@ -186,10 +190,7 @@ class MeshConverter:
                 # 3. Builds the plSpaceTree
                 # 4. Clears the SourceSpans
                 dspan.composeGeometry(True, True)
-
-                # Might as well say something else just to fascinate anyone who is playing along
-                # at home (and actually enjoys reading these lawgs)
-                self._report.msg("Bounds and SpaceTree in the saddle", indent=1)
+                inc_progress()
 
     def _export_geometry(self, bo, mesh, materials, geospans):
         geodata = [_GeoData(len(mesh.vertices)) for i in materials]