Poor performance around percentil 85 and on

[daviddelucca]

Hey there!

We have a simple app using FastAPI that execute requests to another endpoint but we are seeing poor performance on percentiles P85, P90 and P99 running around 200/rps - we only see slow responses inside our code because same metrics on API Gateway is not possible to see the same latency problem.

Based on that, I was imagining that we are facing some problem on how we are using aiohttp and we did some refactoring in the code:

• created a singleton aiohttp to expose a single ClientSession;
• tried to remove limit of connections from TCPConnector.

Our code is very simple:

import aiohttp
import asyncio

from socket import AF_INET

class HTTPClient:
   
    @classmethod
    def get_aiohttp_client(cls) -> aiohttp.ClientSession:
        if cls.aiohttp_client is None:            
            connector = aiohttp.TCPConnector(
                family=AF_INET,
                limit=0,
                limit_per_host=0)
            cls.aiohttp_client = aiohttp.ClientSession(connector=connector)

        return cls.aiohttp_client

    
    @classmethod
    async def close_aiohttp_client(cls) -> None:
        if cls.aiohttp_client:
            await cls.aiohttp_client.close()
            cls.aiohttp_client = None

    @classmethod 
    async def query_url(cls, url: str, values: Dict[str, Any]) -> Any: 
        start = time.perf_counter() * 1000 
        client = cls.get_aiohttp_client() 
        payload = _create_value_payload(value) 
        try: 
            async with client.post(url=url, json=payload, headers=headers) as response: 
                value_response = await response.json() 
                end = time.perf_counter() * 1000 
                total_time = round(end - start) 
                logger.debug(f"Time load {value['group']} {value['name']}: {total_time}") 
                return {value['name']: value_response} 
        except Exception as e: 
            logger.error(f"An error occurred: {e}") 
            return {}

async def make_posts(values: List[Dict[str, Any]]) -> List[Dict[str, Any]]:
    async_calls = list()
    for value in values:
        async_calls.append(HTTPClient.query_url('...', value))

    responses = await asyncio.gather(*async_calls)
    responses = [response for response in responses if responses]
    return responses

Any idea how to debug aiohttp to identify what's is wrong with our code? Do you see any smell in this code?

[Dreamsorcerer]

Not really, but what is "poor performance" in actual numbers? One potential issue is the way you are recording the elapsed time. This isn't necessarily the time it takes for the request to be fetched, as any other tasks blocking the event loop would stop the code from resuming and recording the end time.

Not related to your problem, but I'll also suggest leveraging the framework's functionality, rather than using a singleton class. In aiohttp we'd recommend adding it to the app object on startup and then retrieving it with request.app[client_key] in the handler. In FastAPI the recommendation is usually to use their pytest fixture-style dependency injection.

[Dreamsorcerer]

as any other tasks blocking the event loop would stop the code from resuming and recording the end time.

e.g.

async def foo():
    start = ...
    async with sess.get(...) as resp:
        await resp.json()
        end = ...
        time.sleep(10)

Running 10 of these tasks in parallel, I'm only going to see good numbers for the first task that completes, then the second one is going to be over 10s, the third one over 20s, etc. But, the time actually spent fetching the request is insignificant.

So, depending on what other code you are running, could throw your timing off completely.

[daviddelucca]

I am using K6 (k6.io) or JMeter to extract percentiles, the elapsed time is just a debug log.

Our P85 is around 40ms and P90/P99 are abode 150ms.

In aiohttp we'd recommend adding it to the app object on startup and then retrieving it with request.app[client_key] in the handler. In FastAPI the recommendation is usually to use their pytest fixture-style dependency injection.

I will check this, kinda new to Python :)

[Dreamsorcerer]

Yeah, with only 150ms at the high end, it could easily be an issue with recording, as mentioned above.
In particular, the json decoding is blocking code, so if you make 200 simultaneous requests and every one of them takes 1ms to decode the JSON, then the last request could record a time of 200ms, even though the actual network request may have been completed within 5ms.

[daviddelucca]

Even when I am not looking into logs? I didn't get it. K6 and JMeter doesnt look for my logs also.

When I check metrics on API Gateway, it shows all requests are around 50-60ms but on test results shows mentioned percentiles.

[Dreamsorcerer]

Sorry, I'm not too familiar with your tools. K6 is load testing, right? So, you're saying that the request to the endpoint is taking that long in total?

Again, the same issue could be happening, as the response obviously won't be sent until the handler completes. So, again, if there's 200 handlers running and each of them needs 1ms to decode the JSON, then you're looking at 200ms for the last one to complete.

Looking at response times though also adds FastAPI logic into your testing, which could have a number of other performance issues. So, would be useful to have a reproducer written fully in aiohttp, if you want us to investigate further.