call_next method takes longer than the actual time required

[juyunsang]

First Check

• I added a very descriptive title to this issue.
• I used the GitHub search to find a similar issue and didn't find it.
• I searched the FastAPI documentation, with the integrated search.
• I already searched in Google "How to X in FastAPI" and didn't find any information.
• I already read and followed all the tutorial in the docs and didn't find an answer.
• I already checked if it is not related to FastAPI but to Pydantic.
• I already checked if it is not related to FastAPI but to Swagger UI.
• I already checked if it is not related to FastAPI but to ReDoc.

Commit to Help

• I commit to help with one of those options 👆

Example Code

from fastapi import APIRouter, Request
from fastapi import FastAPI
from fastapi_utils.cbv import cbv

app = FastAPI()

@app.middleware('http')
async def log_middleware(request: Request, call_next):
    request.state.timer = Timer()
    request.state.timer.start('callNextTime')
    response = await call_next(request)
    request.state.timer.end('callNextTime')

router = APIRouter()
@cbv(router)
class TestRouter:
    @router.post('/')
    async def post(self, request:Request):
        request.state.timer.start('routerTime')
        # Do something
        request.state.timer.end('routerTime')
        return response

Description

When we run the stress test, the callNextTime takes much longer than the routerTime
I'd like to ask why this phenomenon occurs

Operating System

Linux

Operating System Details

No response

FastAPI Version

0.65.2

Python Version

3.8.5

Additional Context

No response

[jhonnattan123]

most likely the method inside the await 'response = await call_next(request)' is performing an operation that takes too long. i invite you to read the async await documentation.

https://fastapi.tiangolo.com/async/

[jgould22]

Are you blocking the event loop at any point in your code? (or using a lib that is)

[rafsaf]

It's expected that it takes longer obviously, between callNextTime there is whole FastAPI magic like machinery of handling requests, when at the same time routerTime is only your piece of code and nothing more.

from fastapi import APIRouter, Request
from fastapi import FastAPI

from time import time

app = FastAPI()


@app.middleware("http")
async def log_middleware(request: Request, call_next):
    request.state.callNextTime = time()
    response = await call_next(request)
    request.state.callNextTime = time() - request.state.callNextTime

    print(request.state.routerTime)
    print(request.state.callNextTime)
    return response


router = APIRouter()


@router.post("/")
async def post(request: Request):
    request.state.routerTime = time()
    # Do something
    x = 0
    for i in range(10000):
        x += i
    request.state.routerTime = time() - request.state.routerTime

    return x


app.include_router(router)

For above similar snippet i get following results (uvicorn)
0.0008385181427001953
0.001611948013305664

~2x difference, in your example it is ~5-7x, I have no idea what is from fastapi_utils.cbv import cbv and what is does, I would look into it first, because almost for sure it is your bottleneck here.

[Kludex]

Kludex/starlette#1640