Tasks are not being deferred/delayed correctly when raising Retry

[williamle92]

Hello,

I created a test to check if my tasks are being deferred correctly before being retried. I noticed that timing does not add up when I raise a retry. I am assuming that if a task is retried four times with a 1.5 multiplier delay, I should expect the total time elapsed to be over 15 seconds. However, the numbers I am seeing are very random. Sometimes, it is over 15 seconds, and sometimes, it is less than 9 seconds.

math:
1st job try fail:
1.5 sec delay -- tot: 1.5 sec
2nd job try fail:
3.0 sec delay -- tot: 4.5 sec
3rd job try fail:
4.5 sec delay --tot: 9.0 sec
4th job try fail:
6.0 sec delay --tot: 15.0 sec

@pytest.mark.asyncio
@pytest.mark.arq_delay
async def test_transactional_email_time_elapsed_with_4_errors(
    arq_redis: ArqRedis, worker: Worker
) -> None:
    async def retry_deferred(ctx):
        job_try: int = ctx["job_try"]
        if job_try <= 4:
            raise Retry(defer=job_try * 1.5)
        return "success"

    start_time: float = time.time()
    await arq_redis.enqueue_job(
        "retry_deferred", _job_id="testing"
    )

    worker: Worker = worker(
        functions=[func(retry_deferred, max_tries=5, name="retry_deferred")]
    )
    await worker.main()

    elapsed_time = time.time() - start_time
    # 1.5 + 3 + 4.5 + 6 = 15 seconds

    assert (
        elapsed_time >= 15
    ), f"Expected elapsed time to be at least 15 seconds, but got {elapsed_time:.2f}"
    assert worker.jobs_complete == 1
    assert worker.jobs_failed == 0
    assert worker.jobs_retried == 4

From the console:

INFO     arq.worker:worker.py:322 Starting worker for 1 functions: retry_deferred
INFO     arq.worker:connections.py:296 redis_version=7.2.5 mem_usage=1.87M clients_connected=3 db_keys=2
INFO     arq.worker:worker.py:544   0.01s → testing:retry_deferred()
INFO     arq.worker:worker.py:565   0.00s ↻ testing:retry_deferred retrying job in 1.50s
INFO     arq.worker:worker.py:544   1.51s → testing:retry_deferred() try=2
INFO     arq.worker:worker.py:565   0.00s ↻ testing:retry_deferred retrying job in 3.00s
INFO     arq.worker:worker.py:544   1.51s → testing:retry_deferred() try=3
INFO     arq.worker:worker.py:565   0.00s ↻ testing:retry_deferred retrying job in 4.50s
INFO     arq.worker:worker.py:544   6.01s → testing:retry_deferred() try=4
INFO     arq.worker:worker.py:565   0.00s ↻ testing:retry_deferred retrying job in 6.00s
INFO     arq.worker:worker.py:544   6.01s → testing:retry_deferred() try=5
INFO     arq.worker:worker.py:588   0.00s ← testing:retry_deferred ● 'success'
=================================================================================================================================================================================================== short test summary info ====================================================================================================================================================================================================
FAILED test_invite_user.py::::test_transactional_email_time_elapsed_with_4_errors - AssertionError: Expected elapsed time to be at least 15 seconds, but got 8.40

arq version 0.24.0

Thank you for your time.