fix: Measure elapsed time after function call

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))

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(
                 #   <https://bugs.python.org/issue28613>
                 await asyncio.sleep(seconds)
             else:
+                details["elapsed"] = time.monotonic() - start
                 await _call_handlers(on_success, **details)
 
                 return ret

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

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