improves profile

Author: David Erb

src/dls_utilpack/profiler.py

@@ -1,20 +1,21 @@
 import logging
 import threading
 import time
-from typing import Optional
+from typing import Dict, Optional
 
 logger = logging.getLogger(__name__)
 
 
 class Context:
     """
-    Class that holds the total execution time and call count of potentially multiple executions of the same label.
-    Reports its contents as a single-line string.
+    Class that holds the start time of an execution block.
+    Meant to be used in a "with" statement.
+    Reports its results to the given profiler at the exit.
 
-    TODO: Make profiles nestable by accumulating them at the context close.
+    This class is not publically accessible.
     """
 
-    def __init__(self, label: str, profiler: Profiler):
+    def __init__(self, label: str, profiler):
         self.__profiler = profiler
 
         self.__label = label
@@ -32,25 +33,24 @@ def __exit__(self, exc_type, exc_val, exc_tb):
 
 class Profile:
     """
-    Class that holds the total execution time and call count of potentially multiple executions of the same label.
+    Class that holds the total execution time and call count
+    of potentially multiple executions of the same label.
     Reports its contents as a single-line string.
-
-    TODO: Make profiles nestable by accumulating them at the context close.
     """
 
     def __init__(self, label):
         self.__label = label
-        self.__seconds = 0.0
-        self.__count = 0
+        self.seconds = 0.0
+        self.count = 0
 
     def __str__(self):
-        if self.__count == 0:
+        if self.count == 0:
             average = 0.0
         else:
-            average = self.__seconds / self.__count
+            average = self.seconds / self.count
 
         return (
-            f"{self.__label} called {self.__count} times"
+            f"{self.__label} called {self.count} times"
             f" for average of {'%0.3f' % average} seconds"
         )
 
@@ -62,38 +62,47 @@ class Profiler:
     """
 
     def __init__(self):
-        self.__profiles = {}
+        self.__profiles: Dict[str, Profile] = {}
         self.__lock = threading.RLock()
 
-    def profile(self, label: str) -> Context:
+    def context(self, label: str) -> Context:
         """
-        Return a context to hold the profile timing.
+        Return a context to hold the profile timing for a code block.
 
         Args:
             label (str): label identifying the profile
 
         Returns:
-            Profile: a new profile object, or previously existing one
+            Context: a new context object
         """
         return Context(label, self)
 
-    def accumulate(self, label: str, seconds: float) -> None:
+    def profile(self, label: str) -> Profile:
         """
-        Accumulate a report into the profile for the given label.
+        Make the accumulation profile for the given label.
         Uses previously existing profile, if any, or makes a new instance.
 
         Args:
             label (str): label identifying the profile
-
-        Returns:
-            Profile: a new profile object, or previously existing one
         """
         with self.__lock:
             profile = self.__profiles.get(label)
             if profile is None:
                 profile = Profile(label)
                 self.__profiles[label] = profile
 
+        return profile
+
+    def accumulate(self, label: str, seconds: float) -> None:
+        """
+        Accumulate a report into the profile for the given label.
+        Uses previously existing profile, if any, or makes a new instance.
+
+        Args:
+            label (str): label identifying the profile
+            seconds (float): the number of seconds to accumulate
+        """
+        profile = self.profile(label)
         profile.seconds += seconds
         profile.count += 1
 

tests/test_profiler.py

@@ -1,6 +1,8 @@
 import asyncio
 import logging
 
+import pytest
+
 from dls_utilpack.profiler import dls_utilpack_global_profiler
 
 # Base class for the tester.
@@ -26,7 +28,34 @@ async def _main_coroutine(
 
         profiler = dls_utilpack_global_profiler()
 
-        with profiler.profile("loop1"):
+        with profiler.context("loop1"):
             await asyncio.sleep(0.1)
 
-        logger.debug(f"profile\n{profiler}")
+        assert profiler.profile("loop1").count == 1
+        assert profiler.profile("loop1").seconds == pytest.approx(0.1, abs=1e-2)
+
+        # -----------------------------------------------------
+        for i in range(0, 2):
+            with profiler.context("loop2"):
+                await asyncio.sleep(0.1)
+
+        assert profiler.profile("loop2").count == 2
+        assert profiler.profile("loop2").seconds == pytest.approx(0.2, abs=1e-2)
+
+        # -----------------------------------------------------
+        # Kind of non-sensical to nest them, but check it anyway.
+        with profiler.context("loop3"):
+            with profiler.context("loop3"):
+                with profiler.context("loop3"):
+                    await asyncio.sleep(0.1)
+
+        assert profiler.profile("loop3").count == 3
+        assert profiler.profile("loop3").seconds == pytest.approx(0.3, abs=1e-2)
+
+        # -----------------------------------------------------
+        s = str(profiler)
+        logger.debug(f"profile\n{s}")
+
+        assert "loop1 called 1 times" in s
+        assert "loop2 called 2 times" in s
+        assert "loop3 called 3 times" in s