Python async co-routine execution time

Question

I'm trying to measure python async function execution time. But I faced with problem because actual point when the function is starting is unknown.

Measurement function code:

def timer(func):
    async def process(func, *args, **params):
        if asyncio.iscoroutinefunction(func):
            print('this function is a coroutine: {}'.format(func.__name__))
            return await func(*args, **params)
        else:
            print('this is not a coroutine')
            return func(*args, **params)

    async def helper(*args, **params):
        print('{}.time'.format(func.__name__))
        start = datetime.datetime.now()
        print(start)

        result = await process(func, *args, **params)

        finish = datetime.datetime.now()
        print('>>> calculated - ', finish - start, 'start-', start, 'finish-', finish)
        return result

    return helper

Rest code:

@timer
async def fetch(name, session):
    url = 'http://localhost:8808/'
    payload = {}

    async with session.put(url, headers=HEADERS, json=payload) as response:
        session.get_connection_count()
        response_data = await response.read()
        result = {'response_code': response.status,
              'response_data': response_data}
    return result


def on_data_received(future):
    # pass
    response_obj = json.loads(future.result()['response_data'])
    response_code = future.result()['response_code']
    device_id = response_obj.get('clientDeviceID')

async def run(r):
    connector = DecoratedTCPConnector(limit_per_host=10000, limit=20000)

    with TimedClientSession(connector=connector) as client:
        for i in range(r):
            id = ''.join([random.choice('01234') for x in range(16)])

            task = asyncio.ensure_future(fetch(id, client))
            task.add_done_callback(on_data_received)
            tasks.append(task)
        return await asyncio.gather(*tasks)

The start time actually is the time when the routine task is added to queue, but I need the time when PUT request is sent.

Any suggestions are welcome.

Answer 1

It's virtually impossible to make exact measurements of latency in asyncio networking (AFAIK, would love to be prooved wrong).

The problem is hinted at in the documentation for create_connection:

...This method is a coroutine which will try to establish the connection in the background...

Since that's the fundamental building block aiohttp uses and it's a coroutine which you can politely ask the event loop to execute when it's ready, rather than CALL RIGHT NOW; it's not really possible to get the exact time the connection is made and therefore request took. (also, technically there's a question of what you call "sent" time, is that including time taken to make the connection, or the time taken to transfer data once the connection is made? do you include name resolution in connection time?)

However, you can do a lot better than the code above, for example the time measured above with timer will include any time waiting for a connection to be available in the session's connection pool.

Here's some code which gets you two times:

• the approximate time the connection is started (the time just before the create_connection coroutine is scheduled)
• and (probably) more accurately the time the connection is made, eg. the time the transport's connection_made is called.

Neither of these times will be perfect but unless your event loop is extremely busy they'll probably be accurate enough for any reasonable measurement.

import asyncio
import functools
from time import time
import aiohttp
from aiohttp.client_proto import ResponseHandler

async def main():
    connection_started_time = None
    connection_made_time = None

    class TimedResponseHandler(ResponseHandler):
        def connection_made(self, transport):
            nonlocal connection_made_time
            connection_made_time = time()
            return super().connection_made(transport)

    class TimedTCPConnector(aiohttp.TCPConnector):
        def __init__(self, *args, **kwargs):
            super().__init__(*args, **kwargs)
            self._factory = functools.partial(TimedResponseHandler, loop=loop)

        async def _create_connection(self, req):
            nonlocal connection_started_time
            connection_started_time = time()
            return await super()._create_connection(req)

    async with aiohttp.ClientSession(connector=TimedTCPConnector(loop=loop)) as session:
        async with session.get('https://www.google.com') as response:
            await response.text()
        print(f'>>> time taken including connection time: {time() - connection_started_time:0.3f}s')
        print(f'>>> time taken once connection made: {time() - connection_made_time:0.3f}s')

loop = asyncio.get_event_loop()
loop.run_until_complete(main())