From ae853ebaa4cfd4061eec4a878df9368abc03fb87 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Edgar=20Ram=C3=ADrez=20Mondrag=C3=B3n?= Date: Fri, 24 Jul 2026 14:51:38 -0600 Subject: [PATCH] fix: Measure elapsed time after function call MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Edgar Ramírez Mondragón --- CHANGELOG.md | 4 ++ backoff/_async.py | 8 ++-- backoff/_sync.py | 8 ++-- tests/test_backoff.py | 80 ++++++++++++++++++++++++++++++------- tests/test_backoff_async.py | 80 ++++++++++++++++++++++++++++++++----- 5 files changed, 148 insertions(+), 32 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 85cf915..a2cc998 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,10 @@ - Python 3.9+ is required [#152](https://github.com/python-backoff/backoff/pull/152) +### Fixed + +- Measure elapsed time after function call [187](https://github.com/python-backoff/backoff/pull/187) + ### Documentation - Fixed some examples [#116](https://github.com/python-backoff/backoff/pull/116) (from [@edgarrmondragon](https://github.com/edgarrmondragon)) diff --git a/backoff/_async.py b/backoff/_async.py index eaad59a..7f905eb 100644 --- a/backoff/_async.py +++ b/backoff/_async.py @@ -116,6 +116,7 @@ async def retry(*args: P.args, **kwargs: P.kwargs) -> T: wait = _init_wait_gen(wait_gen, wait_gen_kwargs) while True: tries += 1 + ret = await target(*args, **kwargs) elapsed = time.monotonic() - start details: _BaseDetails = { "target": target, @@ -125,7 +126,6 @@ async def retry(*args: P.args, **kwargs: P.kwargs) -> T: "elapsed": elapsed, } - ret = await target(*args, **kwargs) if predicate(ret): max_tries_exceeded = tries == max_tries_value max_time_exceeded = ( @@ -200,18 +200,19 @@ async def retry( wait = _init_wait_gen(wait_gen, wait_gen_kwargs) while True: tries += 1 - elapsed = time.monotonic() - start details: _BaseDetails = { "target": target, "args": args, "kwargs": kwargs, "tries": tries, - "elapsed": elapsed, + "elapsed": 0, } try: ret = await target(*args, **kwargs) # type: ignore[misc] # ty:ignore[invalid-await] except exception as e: # type: ignore[misc] # ty:ignore[invalid-exception-caught] + elapsed = time.monotonic() - start + details["elapsed"] = elapsed giveup_result = await giveup(e) max_tries_exceeded = tries == max_tries_value max_time_exceeded = ( @@ -243,6 +244,7 @@ async def retry( # await asyncio.sleep(seconds) else: + details["elapsed"] = time.monotonic() - start await _call_handlers(on_success, **details) return ret diff --git a/backoff/_sync.py b/backoff/_sync.py index 3894585..8296cce 100644 --- a/backoff/_sync.py +++ b/backoff/_sync.py @@ -81,6 +81,7 @@ def retry(*args: P.args, **kwargs: P.kwargs) -> T: wait = _init_wait_gen(wait_gen, wait_gen_kwargs) while True: tries += 1 + ret = target(*args, **kwargs) elapsed = time.monotonic() - start details: _BaseDetails = { "target": target, @@ -90,7 +91,6 @@ def retry(*args: P.args, **kwargs: P.kwargs) -> T: "elapsed": elapsed, } - ret = target(*args, **kwargs) if predicate(ret): max_tries_exceeded = tries == max_tries_value max_time_exceeded = ( @@ -144,18 +144,19 @@ def retry(*args: P.args, **kwargs: P.kwargs) -> T: # type: ignore[return] # ty wait = _init_wait_gen(wait_gen, wait_gen_kwargs) while True: tries += 1 - elapsed = time.monotonic() - start details: _BaseDetails = { "target": target, "args": args, "kwargs": kwargs, "tries": tries, - "elapsed": elapsed, + "elapsed": 0, } try: ret = target(*args, **kwargs) except exception as e: # type: ignore[misc] # ty:ignore[invalid-exception-caught] + elapsed = time.monotonic() - start + details["elapsed"] = elapsed max_tries_exceeded = tries == max_tries_value max_time_exceeded = ( max_time_value is not None and elapsed >= max_time_value @@ -177,6 +178,7 @@ def retry(*args: P.args, **kwargs: P.kwargs) -> T: # type: ignore[return] # ty time.sleep(seconds) else: + details["elapsed"] = time.monotonic() - start _call_handlers(on_success, **details) return ret diff --git a/tests/test_backoff.py b/tests/test_backoff.py index ab92c64..c94ac00 100644 --- a/tests/test_backoff.py +++ b/tests/test_backoff.py @@ -1,7 +1,7 @@ -# ruff: file-ignore[float-equality-comparison] - from __future__ import annotations +import contextlib +import itertools import logging import re import sys @@ -65,7 +65,7 @@ def monotonic(): def giveup(details): assert details["tries"] == 3 - assert details["elapsed"] == 10.000005 + assert details["elapsed"] == pytest.approx(10.000005) @backoff.on_predicate(backoff.expo, jitter=None, max_time=10, on_giveup=giveup) def return_true(log: list[bool], n): @@ -95,7 +95,7 @@ def monotonic(): def giveup(details): assert details["tries"] == 3 - assert details["elapsed"] == 10.000005 + assert details["elapsed"] == pytest.approx(10.000005) def lookup_max_time(): return 10 @@ -338,7 +338,7 @@ def succeeder(*args, **kwargs): "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": i + 1, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -348,7 +348,7 @@ def succeeder(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -390,7 +390,7 @@ def exceptor(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": exceptor._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -448,7 +448,7 @@ def success(*args, **kwargs): "tries": i + 1, "value": False, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } details = successes[0] @@ -458,7 +458,7 @@ def success(*args, **kwargs): "target": success._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": True, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -494,7 +494,7 @@ def emptiness(*args, **kwargs): "target": emptiness._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": None, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -534,7 +534,7 @@ def emptiness(*args, **kwargs): "target": emptiness._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": None, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -580,7 +580,7 @@ def succeeder(*args, **kwargs): "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": i + 1, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -590,7 +590,7 @@ def succeeder(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -635,7 +635,7 @@ def success(*args, **kwargs): "tries": i + 1, "value": False, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } details = successes[0] @@ -645,7 +645,7 @@ def success(*args, **kwargs): "target": success._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": True, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -967,3 +967,53 @@ def test_event_log_levels( assert backoff_log_count == max_tries - 1 assert giveup_log_count == 1 + + +def test_max_time(monkeypatch: pytest.MonkeyPatch) -> None: + elapsed: float = 0 + + def patch_sleep(n: float) -> None: + nonlocal elapsed + elapsed += n + + def monotonic() -> float: + return elapsed + + monkeypatch.setattr("time.sleep", patch_sleep) + monkeypatch.setattr("time.monotonic", monotonic) + + # A good place for property-based testing + for function_runtime, max_time in itertools.product(range(10), repeat=2): + elapsed = 0 + + @backoff.on_exception( + backoff.constant, + RuntimeError, + max_time=max_time, + jitter=None, + ) + def on_exception(): + patch_sleep(function_runtime) # ruff: ignore[function-uses-loop-variable] + raise RuntimeError + + with contextlib.suppress(BaseException): + on_exception() + + # backoff never sleeps past max_time, but the time spent in the + # target's own call isn't capped, so the total can run up to one + # more function call past max_time before giving up. + assert elapsed <= max_time + function_runtime + 1e-9 + + elapsed = 0 + + @backoff.on_predicate( + backoff.constant, + lambda x: False, + max_time=max_time, + jitter=None, + ) + def on_predicate(): + patch_sleep(function_runtime) # ruff: ignore[function-uses-loop-variable] + + on_predicate() + assert elapsed <= max_time + function_runtime + 1e-9 diff --git a/tests/test_backoff_async.py b/tests/test_backoff_async.py index c881dda..b0809c4 100644 --- a/tests/test_backoff_async.py +++ b/tests/test_backoff_async.py @@ -1,4 +1,9 @@ +from __future__ import annotations + import asyncio +import contextlib +import itertools +import time from typing import TYPE_CHECKING import pytest @@ -272,7 +277,7 @@ async def succeeder(*args, **kwargs): "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": i + 1, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -282,7 +287,7 @@ async def succeeder(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -323,7 +328,7 @@ async def exceptor(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": exceptor._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -399,7 +404,7 @@ async def success(*args, **kwargs): "tries": i + 1, "value": False, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } details = log["success"][0] @@ -409,7 +414,7 @@ async def success(*args, **kwargs): "target": success._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": True, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -444,7 +449,7 @@ async def emptiness(*args, **kwargs): "target": emptiness._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": None, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -479,7 +484,7 @@ async def emptiness(*args, **kwargs): "target": emptiness._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": None, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -556,7 +561,7 @@ async def succeeder(*args, **kwargs): "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": i + 1, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), "exception": IsInstance(ValueError), } @@ -566,7 +571,7 @@ async def succeeder(*args, **kwargs): "kwargs": {"foo": 1, "bar": 2}, "target": succeeder._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -612,7 +617,7 @@ async def success(*args, **kwargs): "tries": i + 1, "value": False, "wait": 0, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } details = log["success"][0] @@ -622,7 +627,7 @@ async def success(*args, **kwargs): "target": success._target, # type:ignore[attr-defined] # ty:ignore[unresolved-attribute] "tries": 3, "value": True, - "elapsed": IsFloat(), + "elapsed": IsFloat(gt=0), } @@ -713,3 +718,56 @@ async def coro(): task.cancel() assert await task + + +@pytest.mark.asyncio +async def test_max_time(monkeypatch): + start = time.monotonic() + elapsed: float = 0 + + async def patch_sleep(n: float): + nonlocal elapsed + elapsed += n + + def monotonic(): + nonlocal start, elapsed + return start + elapsed + + monkeypatch.setattr("asyncio.sleep", patch_sleep) + monkeypatch.setattr("time.monotonic", monotonic) + + # A good place for property-based testing + for function_runtime, max_time in itertools.product(range(10), repeat=2): + elapsed = 0 + + @backoff.on_exception( + backoff.constant, + RuntimeError, + max_time=max_time, + jitter=None, + ) + async def on_exception(): + await patch_sleep(function_runtime) # ruff: ignore[function-uses-loop-variable] + raise RuntimeError + + with contextlib.suppress(BaseException): + await on_exception() + + # backoff never sleeps past max_time, but the time spent in the + # target's own call isn't capped, so the total can run up to one + # more function call past max_time before giving up. + assert elapsed <= max_time + function_runtime + 1e-9 + + elapsed = 0 + + @backoff.on_predicate( + backoff.constant, + lambda x: False, + max_time=max_time, + jitter=None, + ) + async def on_predicate(): + await patch_sleep(function_runtime) # ruff: ignore[function-uses-loop-variable] + + await on_predicate() + assert elapsed <= max_time + function_runtime + 1e-9