Statistic `delay_since_first_attempt` does not get updated if the last attempt is successful

[DougMHu]

For some reason, tenacity's statistics don't calculate the elapsed time like I would expect. I would expect the below example to log that 3.5 sec elapsed, but delay_since_first_attempt says 2 sec. I think the statistics don't get updated with the time elapsed following the second to last attempt if the last attempt was successful.

In [40]: attempt_num_list = [1]

In [41]: @retry(stop=stop_after_delay(10), wait=wait_fixed(1))
    ...: def succeed_on_attempt(success_attempt_num, execution_time_s=0.5):
    ...:     print("Attempt {}".format(attempt_num_list[0]))
    ...:     print("Start {}".format(time.time()))
    ...:     time.sleep(execution_time_s)
    ...:     if attempt_num_list[0] != success_attempt_num:
    ...:         attempt_num_list[0] += 1
    ...:         print("Stop {}".format(time.time()))
    ...:         raise Exception
    ...:     print("Stop {}".format(time.time()))
    ...:

In [42]: succeed_on_attempt(3)
Attempt 1
Start 1623168327.531153
Stop 1623168328.031927
Attempt 2
Start 1623168329.0345838
Stop 1623168329.5350487
Attempt 3
Start 1623168330.536717
Stop 1623168331.038352

In [43]: print(succeed_on_attempt.retry.statistics)
{'start_time': 1459638.89, 'attempt_number': 3, 'idle_for': 2, 'delay_since_first_attempt': 2.0}

[DougMHu]

From another thread:

Does line 371 in the listing below just need to move up to 361, so that we set this metric after successful attempts too?

tenacity/tenacity/__init__.py

Lines 355 to 392 in e31e011

	def iter(self, retry_state): # noqa
	fut = retry_state.outcome
	if fut is None:
	if self.before is not None:
	self.before(retry_state)
	return DoAttempt()
	is_explicit_retry = retry_state.outcome.failed and isinstance(
	retry_state.outcome.exception(), TryAgain
	)
	if not (is_explicit_retry or self.retry(retry_state=retry_state)):
	return fut.result()
	if self.after is not None:
	self.after(retry_state=retry_state)
	self.statistics["delay_since_first_attempt"] = retry_state.seconds_since_start
	if self.stop(retry_state=retry_state):
	if self.retry_error_callback:
	return self.retry_error_callback(retry_state=retry_state)
	retry_exc = self.retry_error_cls(fut)
	if self.reraise:
	raise retry_exc.reraise()
	six.raise_from(retry_exc, fut.exception())
	if self.wait:
	sleep = self.wait(retry_state=retry_state)
	else:
	sleep = 0.0
	retry_state.next_action = RetryAction(sleep)
	retry_state.idle_for += sleep
	self.statistics["idle_for"] += sleep
	self.statistics["attempt_number"] += 1
	if self.before_sleep is not None:
	self.before_sleep(retry_state=retry_state)
	return DoSleep(sleep)

Originally posted by @asqui in #84 (comment)

I would set the delay metric immediately before the future result return and not remove the existing setting of the metric. You will create a breaking change for any user that has an after that takes time otherwise.
I haven't used this library in a while and don't know if this statistic is being reported as intended or not.
This is a really old unrelated issue, so I'm going to unsubscribe if you'd like a response from me please explicitly @.

Originally posted by @Brian-Williams in #84 (comment)

[tisba]

We just found this issue, because we were trying to debug the metrics we collect based on statistics. This issue still seems to be happening with 9.0.0.

[jd]

The information you need is already available via retry_state.seconds_since_start, which gives the total wall-clock elapsed time from the first attempt to the last outcome.

delay_since_first_attempt in the statistics dict tracks only the cumulative sleep time between attempts (i.e. idle_for), not the total elapsed time — which is why you saw 2.0 (two 1-second waits) instead of 3.5.

To log elapsed time, use the after callback:

def log_elapsed(retry_state):
    print(f'Finished after {retry_state.seconds_since_start:.3f}s')

@retry(stop=stop_after_attempt(3), wait=wait_fixed(1), after=log_elapsed)
def my_func():
    ...

I've added documentation for RetryCallState attributes (including seconds_since_start) in PR #599. Closing this issue.