Merge pull request #40 from bcdev/forman-39-profiling

Added `profiling` configuration setting

Author: forman

CHANGES.md

@@ -2,6 +2,9 @@
 
 ### Enhancements
 
+* It is now possible to configure runtime profiling of the `zappend`
+  processing using the new configuration setting `profiling`. [#39]
+
 * Allow for passing custom slice sources via the configuration.
   The new configuration setting `slice_source` is the name of a class 
   derived from `zappend.api.SliceSource` or a function that creates an instance 

docs/config.md

@@ -187,6 +187,49 @@ Type _boolean_.
 If 'true', log only what would have been done, but don't apply any changes.
 Defaults to `false`.
 
+### `profiling`
+
+Profiling configuration. Allows for runtime profiling of the processing.
+Must be one of the following:
+
+* Type _boolean_.
+  If set, profiling is enabled and output is logged using level INFO. Otherwise, profiling is disabled.
+
+* Type _string_.
+  Profile path. Enables profiling and writes a profiling report to given path.
+
+* Type _object_.
+  
+  * `enabled`:
+    Type _boolean_.
+    Enable or disable profiling.
+  
+  * `path`:
+    Type _string_.
+    Local file path for profiling output.
+  
+  * `log_level`:
+    Log level. Use 'NOTSET' to disable logging.
+    Defaults to `"INFO"`.
+    Must be one of `"CRITICAL", "ERROR", "WARNING", "INFO", "DEBUG", "NOTSET"`.
+  
+  * `keys`:
+    Type _array_.
+    Sort output according to the supplied column names. Refer to [Stats.sort_stats(*keys)](https://docs.python.org/3/library/profile.html#pstats.Stats.sort_stats).
+    Defaults to `["tottime"]`.
+    
+    Must be one of `"calls", "cumulative", "cumtime", "file", "filename", "module", "ncalls", "pcalls", "line", "name", "nfl", "stdname", "time", "tottime"`.
+  
+  * `restrictions`:
+    Type _array_.
+    Used to limit the list down to the significant entries in the profiling report. Refer to [Stats.print_stats(*restrictions)](https://docs.python.org/3/library/profile.html#pstats.Stats.print_stats).
+    
+    Must be one of the following:
+    * Type _integer_.
+    * Type _number_.
+    * Type _string_.
+  
+
 ### `logging`
 
 Type _object_.

docs/guide.md

@@ -618,6 +618,49 @@ zappend(["slice-1.nc", "slice-2.nc", "slice-3.nc"],
         slice_source=MySliceSource)
 ```
 
+## Profiling
+
+Runtime profiling is very important for understanding program runtime behavior 
+and performance. The configuration setting `profiling` can be used to
+analyse and improve the runtime performance of `zappend` itself as well as 
+the runtime performance of the computation of in-memory slices passed to the
+`zappend()` function.
+
+To log the output of the profiling with level `INFO` (see next section 
+[Logging](#logging)), you can use the value `true`:
+
+```json
+{
+    "profiling": true
+}
+```
+
+If you like to see the output in a file too, then set `profiling` to the 
+desired local file path:
+
+```json
+{
+    "profiling": "perf.out"
+}
+```
+
+You can also set `profiling` to an object that allows for fine-grained 
+control of the runtime logging: 
+
+```json
+{
+    "profiling": {
+        "log_level": "WARNING",
+        "path": "perf.out",
+        "keys": ["tottime", "time", "ncalls"]
+    }
+}
+```
+
+Please refer to section [`profiling`](config.md#profiling) in 
+the [Configuration Reference](config.md) for more details.
+
+
 ## Logging
 
 The `zappend` logging output is configured using the `logging` setting.

tests/test_api.py

@@ -1,7 +1,7 @@
 # Copyright © 2024 Norman Fomferra
 # Permissions are hereby granted under the terms of the MIT License:
 # https://opensource.org/licenses/MIT.
-
+import os
 import unittest
 
 import xarray as xr
@@ -28,3 +28,29 @@ def test_some_slices(self):
         self.assertEqual({"time": 9, "y": 50, "x": 100}, ds.sizes)
         self.assertEqual({"chl", "tsm"}, set(ds.data_vars))
         self.assertEqual({"time", "y", "x"}, set(ds.coords))
+
+    def test_some_slices_with_profiling(self):
+        slices = [
+            "memory://slice-1.zarr",
+            "memory://slice-2.zarr",
+            "memory://slice-3.zarr",
+        ]
+        for uri in slices:
+            make_test_dataset(uri=uri)
+
+        target_dir = "memory://target.zarr"
+        try:
+            zappend(
+                slices,
+                config={
+                    "target_dir": target_dir,
+                    "profiling": {
+                        "path": "prof.out",
+                        "keys": ["tottime", "time", "ncalls"],
+                    },
+                },
+            )
+            self.assertTrue(os.path.exists("prof.out"))
+        finally:
+            if os.path.exists("prof.out"):
+                os.remove("prof.out")

tests/test_cli.py

@@ -1,7 +1,7 @@
 # Copyright © 2024 Norman Fomferra
 # Permissions are hereby granted under the terms of the MIT License:
 # https://opensource.org/licenses/MIT.
-import os
+
 import unittest
 from click.testing import CliRunner
 
@@ -104,27 +104,3 @@ def test_some_slices_and_no_target(self):
             "Error: Missing 'target_dir' in configuration\n", result.output
         )
         self.assertFalse(FileObj("memory://target.zarr").exists())
-
-    def test_profiling(self):
-        make_test_dataset(uri="memory://slice-1.zarr")
-        make_test_dataset(uri="memory://slice-2.zarr")
-        make_test_dataset(uri="memory://slice-3.zarr")
-
-        runner = CliRunner()
-        # noinspection PyTypeChecker
-        result = runner.invoke(
-            zappend,
-            [
-                "--profiling",
-                "prof.out",
-                "--target",
-                "memory://target.zarr",
-                "memory://slice-1.zarr",
-                "memory://slice-2.zarr",
-                "memory://slice-3.zarr",
-            ],
-        )
-        self.assertEqual("", result.output)
-        self.assertEqual(0, result.exit_code)
-        self.assertTrue(FileObj("prof.out").exists())
-        os.unlink("prof.out")

tests/test_config.py

@@ -234,6 +234,7 @@ def test_get_config_schema(self):
                 "included_variables",
                 "logging",
                 "persist_mem_slices",
+                "profiling",
                 "slice_engine",
                 "slice_polling",
                 "slice_source",

tests/test_log.py

@@ -1,12 +1,13 @@
 # Copyright © 2024 Norman Fomferra
 # Permissions are hereby granted under the terms of the MIT License:
 # https://opensource.org/licenses/MIT.
+
 import logging
 import unittest
-from click.testing import CliRunner
 
-from zappend.log import logger
 from zappend.log import configure_logging
+from zappend.log import get_log_level
+from zappend.log import logger
 
 
 class LogTest(unittest.TestCase):
@@ -43,3 +44,13 @@ def test_configure_logging(self):
             logger.setLevel(old_level)
             for h in old_handlers:
                 logger.addHandler(h)
+
+    def test_get_log_level(self):
+        self.assertEqual(logging.DEBUG, get_log_level("DEBUG"))
+        self.assertEqual(logging.INFO, get_log_level("INFO"))
+        self.assertEqual(logging.WARNING, get_log_level("WARN"))
+        self.assertEqual(logging.WARNING, get_log_level("WARNING"))
+        self.assertEqual(logging.ERROR, get_log_level("ERROR"))
+        self.assertEqual(logging.CRITICAL, get_log_level("CRITICAL"))
+        self.assertEqual(logging.NOTSET, get_log_level("NOTSET"))
+        self.assertEqual(logging.NOTSET, get_log_level("CRASS"))

tests/test_profiler.py

@@ -0,0 +1,82 @@
+# Copyright © 2024 Norman Fomferra
+# Permissions are hereby granted under the terms of the MIT License:
+# https://opensource.org/licenses/MIT.
+
+import logging
+import os
+import unittest
+
+from zappend.profiler import Profiler
+
+
+class ProfilerTest(unittest.TestCase):
+    def test_disabled(self):
+        profiler = Profiler(None)
+        self.assert_profiler_config(profiler, False)
+        with profiler:
+            pass
+
+        profiler = Profiler(False)
+        self.assert_profiler_config(profiler, False)
+        with profiler:
+            pass
+
+        profiler = Profiler({"enabled": False})
+        self.assert_profiler_config(profiler, False)
+        with profiler:
+            pass
+
+        profiler = Profiler({"log_level": "NOTSET"})
+        self.assert_profiler_config(profiler, False, "NOTSET")
+        with profiler:
+            pass
+
+        profiler = Profiler({"enabled": True, "log_level": "NOTSET"})
+        self.assert_profiler_config(profiler, False, "NOTSET")
+        with profiler:
+            pass
+
+    def test_enabled(self):
+        profiler = Profiler(True)
+        self.assert_profiler_config(profiler, True, "INFO")
+        with profiler:
+            pass
+
+        profiler = Profiler("prof.out")
+        self.assert_profiler_config(profiler, True, "INFO", "prof.out")
+        try:
+            with profiler:
+                pass
+            self.assertTrue(os.path.exists("prof.out"))
+        finally:
+            if os.path.exists("prof.out"):
+                os.remove("prof.out")
+
+        profiler = Profiler({"path": "prof.out", "log_level": "DEBUG"})
+        self.assert_profiler_config(profiler, True, "DEBUG", "prof.out")
+        try:
+            with profiler:
+                pass
+            self.assertTrue(os.path.exists("prof.out"))
+        finally:
+            if os.path.exists("prof.out"):
+                os.remove("prof.out")
+
+    def assert_profiler_config(
+        self,
+        profiler: Profiler,
+        expected_enabled,
+        expected_log_level="INFO",
+        expected_path=None,
+        expected_keys=None,
+        expected_restrictions=None,
+    ):
+        if expected_keys is None:
+            expected_keys = ["tottime"]
+        if expected_restrictions is None:
+            expected_restrictions = []
+        self.assertEqual(expected_enabled, profiler.enabled)
+        self.assertEqual(expected_log_level, profiler.log_level)
+        self.assertEqual(expected_path, profiler.path)
+        self.assertEqual(expected_keys, profiler.keys)
+        self.assertEqual(expected_restrictions, profiler.restrictions)

zappend/api.py

@@ -1,10 +1,8 @@
 # Copyright © 2024 Norman Fomferra
 # Permissions are hereby granted under the terms of the MIT License:
 # https://opensource.org/licenses/MIT.
-from cProfile import Profile
-from io import StringIO
-from pstats import Stats
-from typing import Iterable, Any, Literal
+
+from typing import Any, Iterable
 
 from .config import ConfigItem
 from .config import ConfigLike
@@ -17,7 +15,6 @@
 from .slice import SliceSource
 from .slice import to_slice_factories
 from .slice import to_slice_factory
-from .log import logger
 
 
 __all__ = [
@@ -34,13 +31,10 @@
     "to_slice_factory",
 ]
 
-_TOTAL_TIME: Literal["tottime"] = "tottime"
-
 
 def zappend(
     slices: Iterable[SliceObj | SliceFactory],
     config: ConfigLike = None,
-    profiling=None,
     **kwargs: Any,
 ):
     """
@@ -65,25 +59,8 @@ def zappend(
             May be a file path or URI, a ``dict``, ``None``, or a sequence of
             the aforementioned. If a sequence is used, subsequent configurations
             are incremental to the previous ones.
-        profiling: Path for profiling output.
-            Switches on profiling
         kwargs: Additional configuration parameters.
             Can be used to pass or override configuration values in *config*.
     """
     processor = Processor(config, **kwargs)
-
-    if profiling:
-        profile = Profile()
-        logger.info(f"profiling ...")
-        profile.enable()
-
     processor.process_slices(slices)
-
-    if profiling:
-        profile.disable()
-        results = StringIO()
-        stats = Stats(profile, stream=results)
-        stats.sort_stats(_TOTAL_TIME).print_stats()
-        with open(profiling, "w") as f:
-            f.write(results.getvalue())
-        logger.info(f"profiling output written to {profiling}")

zappend/cli.py

@@ -28,7 +28,6 @@
     is_flag=True,
     help="Run the tool without creating, changing," " or deleting any files.",
 )
-@click.option("--profiling", help="Path for profiling output. Switches on profiling.")
 @click.option(
     "--help-config",
     metavar="json|md",
@@ -40,7 +39,6 @@ def zappend(
     config: tuple[str, ...],
     target: str | None,
     dry_run: bool,
-    profiling: str,
     help_config: str | None,
 ):
     """Create or update a Zarr datacube TARGET from slice datasets SLICES.
@@ -63,13 +61,7 @@ def zappend(
 
     # noinspection PyBroadException
     try:
-        zappend(
-            slices,
-            config=config,
-            target_dir=target,
-            dry_run=dry_run,
-            profiling=profiling,
-        )
+        zappend(slices, config=config, target_dir=target, dry_run=dry_run)
     except BaseException as e:
         raise click.ClickException(f"{e}") from e