From a9003993fab63b9e94e5b8aaed3bc60011e38f2f Mon Sep 17 00:00:00 2001 From: Evgenii Alekseev Date: Tue, 27 Aug 2024 00:27:37 +0300 Subject: [PATCH] feat: add timer for metrics purposes --- src/ahriman/application/lock.py | 2 +- src/ahriman/core/spawn.py | 12 ++- src/ahriman/models/metrics_timer.py | 93 ++++++++++++++++++++++ src/ahriman/models/process_status.py | 4 +- src/ahriman/models/waiter.py | 19 +++-- tests/ahriman/models/test_metrics_timer.py | 42 ++++++++++ tests/ahriman/models/test_waiter.py | 11 ++- 7 files changed, 159 insertions(+), 24 deletions(-) create mode 100644 src/ahriman/models/metrics_timer.py create mode 100644 tests/ahriman/models/test_metrics_timer.py diff --git a/src/ahriman/application/lock.py b/src/ahriman/application/lock.py index d4b5fe39..ebaeb3ea 100644 --- a/src/ahriman/application/lock.py +++ b/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) """ diff --git a/src/ahriman/core/spawn.py b/src/ahriman/core/spawn.py index c77bde31..c6a19d66 100644 --- a/src/ahriman/core/spawn.py +++ b/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) diff --git a/src/ahriman/models/metrics_timer.py b/src/ahriman/models/metrics_timer.py new file mode 100644 index 00000000..46436c60 --- /dev/null +++ b/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 . +# +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 diff --git a/src/ahriman/models/process_status.py b/src/ahriman/models/process_status.py index 867373d1..99eb2f44 100644 --- a/src/ahriman/models/process_status.py +++ b/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 diff --git a/src/ahriman/models/waiter.py b/src/ahriman/models/waiter.py index 70ff3104..395ace94 100644 --- a/src/ahriman/models/waiter.py +++ b/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) diff --git a/tests/ahriman/models/test_metrics_timer.py b/tests/ahriman/models/test_metrics_timer.py new file mode 100644 index 00000000..984e4410 --- /dev/null +++ b/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() diff --git a/tests/ahriman/models/test_waiter.py b/tests/ahriman/models/test_waiter.py index 5af432a2..af328c9d 100644 --- a/tests/ahriman/models/test_waiter.py +++ b/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: