tenacity icon indicating copy to clipboard operation
tenacity copied to clipboard

Access to elapsed time

Open ematta opened this issue 7 years ago • 6 comments

Is there any way to access the elapsed time and how many retries were attempted for a particular method?

ematta avatar Jul 31 '17 20:07 ematta

If you run the statistics example from the readme:

@retry(stop=stop_after_attempt(3))
def raise_my_exception():
    raise MyException("Fail")

try:
    raise_my_exception()
except Exception:
    pass

print(raise_my_exception.retry.statistics)

It outputs the info I believe you are looking for ('delay_since_first_attempt' and 'attempt_number'): {'attempt_number': 3, 'idle_for': 0, 'start_time': 754342.237794953, 'delay_since_first_attempt': 0.0001827329397201538}

It may be valuable to put that after the example in the readme to make that information more obvious.

Brian-Williams avatar Jul 31 '17 21:07 Brian-Williams

Awesome! Thank you very much for this!

ematta avatar Jul 31 '17 21:07 ematta

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 avatar Jun 08 '21 17:06 DougMHu

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

https://github.com/jd/tenacity/blob/e31e0119aa37919d90a388177add3ba027ec0f3f/tenacity/init.py#L355-L392

asqui avatar Jun 08 '21 21:06 asqui

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 @.

Brian-Williams avatar Jun 09 '21 00:06 Brian-Williams

Sorry all, I should have created a separate issue. I just created #303 and referenced your comments there. Thanks so much for the quick replies 🙏

DougMHu avatar Jun 09 '21 16:06 DougMHu