diff --git a/src/dls_utilpack/profiler.py b/src/dls_utilpack/profiler.py index 0c5b9b8..41dfabb 100644 --- a/src/dls_utilpack/profiler.py +++ b/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,31 +62,28 @@ 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) @@ -94,6 +91,18 @@ def accumulate(self, label: str, seconds: float) -> 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 diff --git a/tests/test_profiler.py b/tests/test_profiler.py index 410638e..169cd2b 100644 --- a/tests/test_profiler.py +++ b/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