Timeouts checked once a second (?)

[haizaar]

🐞 Describe the bug

aiohttp.ClientTimeout.total is annotated to accept floats, yet my observations are that timeout condition is checked once a second. Is it a bug or feature? E.g. requests library does not have this limitation and easily works with 0.01 timeouts in my tests. I realize that sub-second timeouts are quite synthetic, but very useful for tests.

💡 To Reproduce
aiohttp 3.6.2 on Ubuntu 18.04 amd64 with CPython 3.8.3.

Consider the below code:

import asyncio
import socket
import sys
import time

import aiohttp
from aiohttp import web


async def hello(request):
    await asyncio.sleep(10)
    return web.Response(text="Hello, world")


async def run_client(port: int, timeout: float):
    async with aiohttp.ClientSession() as session:
        while True:
            start = time.monotonic()
            try:
                await session.get(f"http://localhost:{port}/",
                                  timeout=aiohttp.ClientTimeout(total=timeout))
            except asyncio.TimeoutError:
                pass
            took = time.monotonic() - start
            print(f"expected={timeout}, took={took:.3f}, skew={took-timeout:.3f}")


async def amain(timeout: float):
    app = web.Application()
    app.add_routes([web.get('/', hello)])
    runner = web.AppRunner(app)
    await runner.setup()

    sock = socket.socket(socket.AF_INET, type=socket.SOCK_STREAM)
    sock.bind(("localhost", 0))
    _, port = sock.getsockname()

    site = web.SockSite(runner=runner, sock=sock)
    await site.start()

    await run_client(port, timeout)


if __name__ == "__main__":
    asyncio.run(amain(float(sys.argv[1])))

No matter what the timeout value is, the actual timeout is always in multiples of 1 second as you can see in the took value below:

$ python /tmp/timeout-bug.py 0.1
expected=0.1, took=0.726, skew=0.626
expected=0.1, took=1.000, skew=0.900
expected=0.1, took=1.000, skew=0.900
python /tmp/timeout-bug.py 0.8
expected=0.8, took=1.414, skew=0.614
expected=0.8, took=0.999, skew=0.199
expected=0.8, took=1.000, skew=0.200
expected=0.8, took=1.001, skew=0.201
python /tmp/timeout-bug.py 1.1
expected=1.1, took=1.473, skew=0.373
expected=1.1, took=2.000, skew=0.900
expected=1.1, took=2.000, skew=0.900
expected=1.1, took=2.000, skew=0.900
python /tmp/timeout-bug.py 2.1
expected=2.1, took=2.158, skew=0.058
expected=2.1, took=2.999, skew=0.899
expected=2.1, took=3.001, skew=0.901
expected=2.1, took=2.998, skew=0.898

💡 Expected behavior
Is this intentional or a bug?

📋 **Your version of the Python**
<!-- Attach your version of the Python. -->
```console
$ python --version
Python 3.8.3
...

📋 Your version of the aiohttp/yarl/multidict distributions

$ python -m pip show aiohttp
Name: aiohttp
Version: 3.6.2
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author: Nikolay Kim
Author-email: [email protected]
License: Apache 2
Location: /home/.../lib/python3.8/site-packages
Requires: multidict, chardet, async-timeout, attrs, yarl
Required-by: 

$ python -m pip show multidict
Name: aiohttp
Version: 3.6.2
Summary: Async http client/server framework (asyncio)
Home-page: https://github.com/aio-libs/aiohttp
Author: Nikolay Kim
Author-email: [email protected]
License: Apache 2
Location: /home/.../lib/python3.8/site-packages
Requires: multidict, chardet, async-timeout, attrs, yarl
Required-by: 
$ python -m pip show multidict
Name: multidict
Version: 4.7.6
Summary: multidict implementation
Home-page: https://github.com/aio-libs/multidict
Author: Andrew Svetlov
Author-email: [email protected]
License: Apache 2
Location: /home/.../lib/python3.8/site-packages
Requires: 
Required-by: yarl, aiohttp

$ python -m pip show yarl
Name: yarl
Version: 1.4.2
Summary: Yet another URL library
Home-page: https://github.com/aio-libs/yarl/
Author: Andrew Svetlov
Author-email: [email protected]
License: Apache 2
Location: /home/.../lib/python3.8/site-packages
Requires: idna, multidict
Required-by: aiohttp

📋 Additional context

[asvetlov]

Thanks for the question!
The reason was the reducing amount of event loop wakeups when working with massive (thousands and millions) number of concurrent requests.
In the real world, tiny timeouts are not used AFAIK.

Rather rounding to milliseconds (or not rounding at all) I prefer configuring the precession by aiohttp.ClientTimeout. We can provide a float (e.g. 0.001 vs. 1.0) or a callable that accepts loop.time() and timeout and returns absolute timestamp when the timeout expires. By default, the implementation is:

def timeout_at(now: float, timeout: float) -> float:
    return ceil(now + timeout)

What do you think?

[haizaar]

Hi Andrew,

I totally agree that very short timeouts are not used in real world scenarios but will reduce my test cycle from 15 seconds to 1 :) in my http-noah project.

If what you are referring to is as in #4851 then it looks very good to me - nothing will practically change for real-world timeouts and shorter ones will now work.

[luckydenis]

Hi!
When rounding, the call processing time increases. This doesn't seem to be what we want. I looked at work after the function call and didn't notice a strong need for rounding.

Test stand

from random import uniform
from math import ceil, trunc


timeout = 0.1

def use_round():
    timer = uniform(1, 300)
    round(timer + timeout, 3)
    
    
def use_ceil():
    timer = uniform(1, 300)
    ceil(timer + timeout)
    

def use_castom():
    timer = uniform(1, 300)
    (ceil(timer + timeout) * 100) / 100

    
def use_not_round():
    timer = uniform(1, 300)
    timer + timeout
    
    
%timeit -n 10000 -r 100 use_not_round()
%timeit -n 10000 -r 100 use_ceil()
%timeit -n 10000 -r 100 use_castom()
%timeit -n 10000 -r 100 use_round()

stdin:

371 ns ± 97.9 ns per loop (mean ± std. dev. of 100 runs, 10000 loops each)
461 ns ± 53.9 ns per loop (mean ± std. dev. of 100 runs, 10000 loops each)
542 ns ± 95.2 ns per loop (mean ± std. dev. of 100 runs, 10000 loops each)
879 ns ± 146 ns per loop (mean ± std. dev. of 100 runs, 10000 loops each)

[haizaar]

The code in #4851 does not suggest any rounds as far as I can tell. Am I missing anything?

Regardless, why do you think <0.5 microsecond is significant in real-world Python HTTP clients?

[luckydenis]

It seems to me that rounding is not required here, especially since we are losing the speed of calling the function. A little here, a little somewhere else, the overall performance is getting worse.

[asvetlov]

The question is not about the time of cell() vs round() performance but the number of the event loop wakeups per minute.
With many concurrent clients the loop can wakeup too often on timeouts, every look iteration is not for free.

The loop is overwhelmed by loop.call_later() with small delays, these delays point to different absolute times.
When cell-ing, the number of delays is the same but they are happening at predictable timestamps (many delays every second). It requires a single loop wakeup that handles multiple callbacks at once. This is the real optimization source, not the cell performance.

[haizaar]

Thanks Andrew,
So to sum it up we are talking about today situation where tiny timeouts do not slow the server but are not truly honoured either vs the suggested change where large amounts of requests all using tiny timeouts can hinder loop effectiveness, right?

If so, I'm rather in favor of applying the suggested change. For normal workload nothing will change; for test workloads with tiny timeouts there would be no impact since the scale is typically small; for extremer corner case of large workload with tiny timeouts now developer at least will have a choice to prefer tiny timeouts and bite the impact or switch back to large timeouts in his app.

Maybe a slight improvement to the current proposal would be to still round/ceil loop.call_later() to the whole second but only for timeout values larger than, say, 2-3 seconds. This way absolutely nothing will change for the real workloads and aiohttp can still process multiple callbacks in a single wakeup in those cases.

WDYT?

[asvetlov]

Sorry for the pause.
Rounding for timeouts larger than 5 seconds only is the perfect solution (I prefer 5 over 2-3).
Disabling the rounding at all is not satisfactory because it degrades both server and client performance under high load (many concurrent requests are sent or received).

[haizaar]

Happy to hear. @luckydenis do you want to proceed with your PR as per Andre's last comments?