feat: add timer for metrics purposes

src/ahriman/application/lock.py

@@ -59,7 +59,7 @@ class Lock(LazyLogging):
             >>> configuration = Configuration()
             >>> try:
             >>>     with Lock(args, RepositoryId("x86_64", "aur-clone"), configuration):
-            >>>         perform_actions()
+            >>>         do_something()
             >>> except Exception as exception:
             >>>     handle_exceptions(exception)
     """

src/ahriman/core/spawn.py

@@ -20,7 +20,6 @@
 from __future__ import annotations
 
 import argparse
-import time
 import uuid
 
 from collections.abc import Callable, Iterable
@@ -28,6 +27,7 @@ from multiprocessing import Process, Queue
 from threading import Lock, Thread
 
 from ahriman.core.log import LazyLogging
+from ahriman.models.metrics_timer import MetricsTimer
 from ahriman.models.pkgbuild_patch import PkgbuildPatch
 from ahriman.models.process_status import ProcessStatus
 from ahriman.models.repository_id import RepositoryId
@@ -90,11 +90,9 @@ class Spawn(Thread, LazyLogging):
             process_id(str): process unique identifier
             queue(Queue[ProcessStatus | None]): output queue
         """
-        start_time = time.monotonic()
-        result = callback(args, repository_id)
-        stop_time = time.monotonic()
-
-        consumed_time = int(1000 * (stop_time - start_time))
+        with MetricsTimer() as timer:
+            result = callback(args, repository_id)
+            consumed_time = timer.elapsed
 
         queue.put(ProcessStatus(process_id, result, consumed_time))
 
@@ -271,7 +269,7 @@ class Spawn(Thread, LazyLogging):
         """
         for terminated in iter(self.queue.get, None):
             self.logger.info("process %s has been terminated with status %s, consumed time %ss",
-                             terminated.process_id, terminated.status, terminated.consumed_time / 1000)
+                             terminated.process_id, terminated.status, terminated.consumed_time)
 
             with self._lock:
                 process = self.active.pop(terminated.process_id, None)

src/ahriman/models/metrics_timer.py

@@ -0,0 +1,93 @@
+#
+# Copyright (c) 2021-2024 ahriman team.
+#
+# This file is part of ahriman
+# (see https://github.com/arcan1s/ahriman).
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+#
+import time
+
+from types import TracebackType
+from typing import Literal, Self
+
+from ahriman.core.exceptions import InitializeError
+
+
+class MetricsTimer:
+    """
+    metrics implementation
+
+    Attributes:
+        start_time(float | None): timer start time in monotonic time
+
+    Examples:
+        This class implements simple timer which allows to measure the time elapsed of the function. Usually it should
+        be used like::
+
+            >>> with MetricsTimer() as timer:
+            >>>     do_something()
+            >>>     print("Time elapsed for first function: %f", timer.elapsed)
+            >>>     do_something_different()
+            >>>     print("Time elapsed for all functions: %f", timer.elapsed)
+    """
+
+    def __init__(self) -> None:
+        """
+        default constructor
+        """
+        self.start_time: float | None = None
+
+    @property
+    def elapsed(self) -> float:
+        """
+        get elapsed time since the start of the timer
+
+        Returns:
+            float: time elapsed in seconds
+
+        Raises:
+            InitializeError: in case if timer was not initialized correctly
+        """
+        if self.start_time is None:
+            raise InitializeError("Timer must be started in the context manager")
+
+        stop_time = time.monotonic()
+        consumed_time_ms = int(1000 * (stop_time - self.start_time))
+        return consumed_time_ms / 1000
+
+    def __enter__(self) -> Self:
+        """
+        start timer context
+
+        Returns:
+            Self: always instance of self
+        """
+        self.start_time = time.monotonic()
+        return self
+
+    def __exit__(self, exc_type: type[Exception] | None, exc_val: Exception | None,
+                 exc_tb: TracebackType) -> Literal[False]:
+        """
+        finish timer context
+
+        Args:
+            exc_type(type[Exception] | None): exception type name if any
+            exc_val(Exception | None): exception raised if any
+            exc_tb(TracebackType): exception traceback if any
+
+        Returns:
+            Literal[False]: always ``False`` (do not suppress any exception)
+        """
+        return False

src/ahriman/models/process_status.py

@@ -28,9 +28,9 @@ class ProcessStatus:
     Attributes:
         process_id(str): unique process identifier
         status(bool): process exit code status
-        consumed_time(int): consumed time in ms
+        consumed_time(float): consumed time in seconds
     """
 
     process_id: str
     status: bool
-    consumed_time: int
+    consumed_time: float

src/ahriman/models/waiter.py

@@ -23,6 +23,8 @@ from collections.abc import Callable
 from dataclasses import dataclass, field
 from typing import Literal, ParamSpec
 
+from ahriman.models.metrics_timer import MetricsTimer
+
 
 Params = ParamSpec("Params")
 
@@ -94,25 +96,25 @@ class Waiter:
 
     Attributes:
         interval(float): interval in seconds between checks
-        start_time(float): monotonic time of the waiter start. More likely must not be assigned explicitly
         wait_timeout(float): timeout in seconds to wait for. Negative value will result in immediate exit. Zero value
     means infinite timeout
     """
 
     wait_timeout: float
-    start_time: float = field(default_factory=time.monotonic, kw_only=True)
     interval: float = field(default=10, kw_only=True)
 
-    def is_timed_out(self) -> bool:
+    def is_timed_out(self, elapsed: float) -> bool:
         """
         check if timer is out
 
+        Attributes:
+            elapsed(float): elapsed time in seconds
+
         Returns:
             bool: ``True`` in case current monotonic time is more than :attr:`start_time` and :attr:`wait_timeout`
             doesn't equal to 0
         """
-        since_start = time.monotonic() - self.start_time
-        return self.wait_timeout != 0 and since_start > self.wait_timeout
+        return self.wait_timeout != 0 and elapsed > self.wait_timeout
 
     def wait(self, in_progress: Callable[Params, bool], *args: Params.args, **kwargs: Params.kwargs) -> WaiterResult:
         """
@@ -126,9 +128,10 @@ class Waiter:
         Returns:
             WaiterResult: waiter result object
         """
-        while not (timed_out := self.is_timed_out()) and in_progress(*args, **kwargs):
-            time.sleep(self.interval)
-        took = time.monotonic() - self.start_time
+        with MetricsTimer() as timer:
+            while not (timed_out := self.is_timed_out(timer.elapsed)) and in_progress(*args, **kwargs):
+                time.sleep(self.interval)
+            took = timer.elapsed
 
         if timed_out:
             return WaiterTimedOut(took)

tests/ahriman/models/test_metrics_timer.py

@@ -0,0 +1,42 @@
+import pytest
+import time
+
+from ahriman.core.exceptions import InitializeError
+from ahriman.models.metrics_timer import MetricsTimer
+
+
+def test_elapsed() -> None:
+    """
+    must return elapsed time
+    """
+    with MetricsTimer() as timer:
+        value1 = timer.elapsed
+        time.sleep(0.1)
+        value2 = timer.elapsed
+        assert value2 > value1
+
+
+def test_elapsed_exception() -> None:
+    """
+    must raise InitializeError if timer wasn't started in the context manager
+    """
+    timer = MetricsTimer()
+    with pytest.raises(InitializeError):
+        assert timer.elapsed
+
+
+def test_enter() -> None:
+    """
+    must start timer with context manager
+    """
+    with MetricsTimer() as timer:
+        assert timer.start_time > 0
+
+
+def test_exit_with_exception() -> None:
+    """
+    must exit from context manager if an exception is raised
+    """
+    with pytest.raises(ValueError):
+        with MetricsTimer():
+            raise ValueError()

tests/ahriman/models/test_waiter.py

@@ -1,5 +1,4 @@
 import pytest
-import time
 
 from ahriman.models.waiter import Waiter, WaiterResult, WaiterTaskFinished, WaiterTimedOut
 
@@ -37,17 +36,17 @@ def test_is_timed_out() -> None:
     """
     must correctly check if timer runs out
     """
-    assert Waiter(-1).is_timed_out()
-    assert Waiter(1, start_time=time.monotonic() - 10.0).is_timed_out()
-    assert not Waiter(1, start_time=time.monotonic() + 10.0).is_timed_out()
+    assert Waiter(-1).is_timed_out(0.0)
+    assert Waiter(1).is_timed_out(42.0)
+    assert not Waiter(1).is_timed_out(0.42)
 
 
 def test_is_timed_out_infinite() -> None:
     """
     must treat 0 wait timeout as infinite
     """
-    assert not Waiter(0).is_timed_out()
-    assert not Waiter(0, start_time=time.monotonic() - 10.0).is_timed_out()
+    assert not Waiter(0).is_timed_out(0.0)
+    assert not Waiter(0).is_timed_out(-1.0)
 
 
 def test_wait() -> None: