Take into account time elapsed during calls

[yawhide]

Hello,

It seems this library sleeps "duration" amount of time no matter how long the calls take.

See this example:

import datetime
import time

from pyrate_limiter import Duration, Limiter, MemoryQueueBucket, RequestRate

limiter = Limiter(RequestRate(15, Duration.SECOND), bucket_class=MemoryQueueBucket)

@limiter.ratelimit("get_transfers", delay=True)
def hey(counter):
    time.sleep(0.01)
    print(datetime.datetime.now(), counter)

if __name__ == "__main__":
    for i in range(15):
        hey(i)

    for i in range(15):
        hey(i)

    for i in range(15):
        hey(i)

The output shows:

2021-09-21 20:43:14.531809 0
2021-09-21 20:43:14.542202 1
2021-09-21 20:43:14.552524 2
2021-09-21 20:43:14.562810 3
2021-09-21 20:43:14.573070 4
2021-09-21 20:43:14.583382 5
2021-09-21 20:43:14.593741 6
2021-09-21 20:43:14.604055 7
2021-09-21 20:43:14.614501 8
2021-09-21 20:43:14.624727 9
2021-09-21 20:43:14.635107 10
2021-09-21 20:43:14.645440 11
2021-09-21 20:43:14.655796 12
2021-09-21 20:43:14.666227 13
2021-09-21 20:43:14.676648 14
{'error': 'Bucket for get_transfers with Rate 15/1 is already full', 'identity': 'get_transfers', 'rate': '15/1', 'remaining_time': 1}
Rate limit reached; 1 seconds remaining before next request
2021-09-21 20:43:15.688529 0
2021-09-21 20:43:15.698823 1
2021-09-21 20:43:15.709181 2
2021-09-21 20:43:15.719494 3
2021-09-21 20:43:15.729820 4
2021-09-21 20:43:15.740170 5
2021-09-21 20:43:15.750634 6
2021-09-21 20:43:15.760945 7
2021-09-21 20:43:15.771326 8
2021-09-21 20:43:15.781699 9
2021-09-21 20:43:15.792020 10
2021-09-21 20:43:15.802379 11
2021-09-21 20:43:15.812845 12
2021-09-21 20:43:15.823293 13
2021-09-21 20:43:15.833631 14
{'error': 'Bucket for get_transfers with Rate 15/1 is already full', 'identity': 'get_transfers', 'rate': '15/1', 'remaining_time': 1}
Rate limit reached; 1 seconds remaining before next request
2021-09-21 20:43:16.845334 0
2021-09-21 20:43:16.855676 1
2021-09-21 20:43:16.866223 2
2021-09-21 20:43:16.876586 3
2021-09-21 20:43:16.886921 4
2021-09-21 20:43:16.897270 5
2021-09-21 20:43:16.907618 6
2021-09-21 20:43:16.917932 7
2021-09-21 20:43:16.928241 8
2021-09-21 20:43:16.938601 9
2021-09-21 20:43:16.949142 10
2021-09-21 20:43:16.959737 11
2021-09-21 20:43:16.970079 12
2021-09-21 20:43:16.980392 13
2021-09-21 20:43:16.990715 14

I expect the sleep to be (1 - (0.01*15)) seconds (which is around 0.85) but it actually just sleeps 1s instead.

Am I understanding things correctly?

Thanks!

[JWCook]

You're right, looks like the issue is here: https://github.com/vutran1710/PyrateLimiter/blob/d42eba8b5e627f4f187c6a99d89e676dbb72533c/pyrate_limiter/limiter.py#L59-L71

I just added a PR that will fix this, and with those changes this is the output I get with your example:

2021-09-21 17:04:24.394955 0
2021-09-21 17:04:24.405153 1
2021-09-21 17:04:24.415374 2
2021-09-21 17:04:24.425591 3
2021-09-21 17:04:24.435755 4
2021-09-21 17:04:24.445934 5
2021-09-21 17:04:24.456155 6
2021-09-21 17:04:24.466260 7
2021-09-21 17:04:24.476380 8
2021-09-21 17:04:24.486585 9
2021-09-21 17:04:24.496774 10
2021-09-21 17:04:24.506926 11
2021-09-21 17:04:24.517071 12
2021-09-21 17:04:24.527207 13
2021-09-21 17:04:24.537315 14
DEBUG:pyrate_limiter.limit_context_decorator:{'error': 'Bucket for get_transfers with Rate 15/1 is already full', 'identity': 'get_transfers', 'rate': '15/1', 'remaining_time': 0.8474824730074033}
INFO:pyrate_limiter.limit_context_decorator:Rate limit reached; 0.8474824730074033 seconds remaining before next request
2021-09-21 17:04:25.396366 0
2021-09-21 17:04:25.406491 1
2021-09-21 17:04:25.416617 2
2021-09-21 17:04:25.426784 3
2021-09-21 17:04:25.436915 4
2021-09-21 17:04:25.447097 5
2021-09-21 17:04:25.457213 6
2021-09-21 17:04:25.467368 7
2021-09-21 17:04:25.477633 8
2021-09-21 17:04:25.487827 9
2021-09-21 17:04:25.498036 10
2021-09-21 17:04:25.508288 11
2021-09-21 17:04:25.518450 12
2021-09-21 17:04:25.528594 13
2021-09-21 17:04:25.538805 14
DEBUG:pyrate_limiter.limit_context_decorator:{'error': 'Bucket for get_transfers with Rate 15/1 is already full', 'identity': 'get_transfers', 'rate': '15/1', 'remaining_time': 0.8473759199987398}
INFO:pyrate_limiter.limit_context_decorator:Rate limit reached; 0.8473759199987398 seconds remaining before next request
2021-09-21 17:04:26.397431 0
2021-09-21 17:04:26.407561 1
2021-09-21 17:04:26.417677 2
2021-09-21 17:04:26.427816 3
2021-09-21 17:04:26.437954 4
2021-09-21 17:04:26.448095 5
2021-09-21 17:04:26.458212 6
2021-09-21 17:04:26.468336 7
2021-09-21 17:04:26.478446 8
2021-09-21 17:04:26.488561 9
2021-09-21 17:04:26.498701 10
2021-09-21 17:04:26.508823 11
2021-09-21 17:04:26.518936 12
2021-09-21 17:04:26.529057 13
2021-09-21 17:04:26.539203 14

[yawhide]

Awesome 😎

[yawhide]

@vutran1710 how long does it take for pypi to get the new version published? I still dont see 2.3.5 on there https://pypi.org/project/pyrate-limiter/#history

[vutran1710]

@vutran1710 how long does it take for pypi to get the new version published? I still dont see 2.3.5 on there https://pypi.org/project/pyrate-limiter/#history

Oh weird, looks like there has been some changes with travis-ci. I'll try to fix it soon

[vutran1710]

$ poetry run cover
============================= test session starts ==============================
platform linux -- Python 3.6.7, pytest-5.4.3, py-1.10.0, pluggy-0.13.1
rootdir: /home/travis/build/[secure]an1710/PyrateLimiter
plugins: asyncio-0.12.0
collected 16 items
tests/test_01.py F
=================================== FAILURES ===================================
__________________________________ test_sleep __________________________________
    def test_sleep():
        rate = RequestRate(6, 5 * Duration.SECOND)
        iterations = 10
        limiter = Limiter(rate)
        push, sleep_count = 0, 0

        for i in range(iterations):
            try:
                for _ in range(2):
                    limiter.try_acquire("test")
                    push += 1
                print(f"Pushed: {push} items")
                sleep(1)
            except BucketFullException as e:
                sleep_time = e.meta_info["remaining_time"]
                print(f"Stuck at {i}, sleep for {sleep_time}")
                sleep_count += 1
                sleep(sleep_time)

>       assert sleep_count == 2
E       assert 3 == 2
tests/test_01.py:33: AssertionError
----------------------------- Captured stdout call -----------------------------
Pushed: 2 items
Pushed: 4 items
Pushed: 6 items
Stuck at 3, sleep for 1.9963931749999944
Pushed: 8 items
Pushed: 10 items
Pushed: 12 items
Stuck at 7, sleep for 1.9917434500000013
Pushed: 14 items
Stuck at 9, sleep for 0.0023172630000090066
=============================== warnings summary ===============================
/home/travis/virtualenv/python3.6.7/lib/python3.6/distutils/__init__.py:4
  /home/travis/virtualenv/python3.6.7/lib/python3.6/distutils/__init__.py:4: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
    import imp
-- Docs: https://docs.pytest.org/en/latest/warnings.html
=========================== short test summary info ============================
FAILED tests/test_01.py::test_sleep - assert 3 == 2

@JWCook apparently using monotonic makes test fail in build environment. You have any idea about this? Oh and btw, it also fails in my machine.

[JWCook]

I'll take a look.

[JWCook]

I don't think time.monotonic() makes any difference here, but now that delay times can be less than 1 second, some of the tests now have less tolerance for small differences in execution time due to different hardware.

In #41 I updated a couple tests that checked for exact remaining_time to check to the nearest 100ms, which should be more than enough to account for those differences. Example: https://github.com/vutran1710/PyrateLimiter/blob/33e90a03f3101ffc9c486bbf8eb6e741248a5ae3/tests/test_01.py#L71

I didn't catch this test, though, since it passed on my machine. I'll update that shortly.

Another thought: some of these tests could be made more precise by using freezegun or time-machine to mock an exact system time instead of using time.sleep(), since that would make the execution time of the test code itself less likely to influence test results. That could be a separate PR, though.

[JWCook]

Looks like tests and deployment are all green now and 2.3.6 is available on PyPI, so I think this can be closed.