Having issues profiling FastAPI calls

[coneybeare]

First, thanks so much for your hard work on this great library. It is a fantastic addition to the python ecosystem!

I am implementing profiling in FastAPI as a middleware, listening for a header val or query arg like the example shows. My middleware setup is a little different, but is added to the call stack just the same

"""Middleware that enables on-demand app profiling when a profile header is passed."""

from fastapi import Request, Response
from fastapi.responses import HTMLResponse, PlainTextResponse
from pyinstrument import Profiler, renderers
from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint

from app.utils import ErrorReporter, Logger

PROFILING_INTERVAL = 0.001  # 1 millisecond
PROFILING_ASYNC_MODE = "enabled"


class ProfilingMiddleware(BaseHTTPMiddleware):
    """Middleware that enables on-demand app profiling when a profile header is passed."""

    async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
        """Middleware that enables on-demand app profiling when a profile header is passed."""
        try:
            profiling = self.should_profile(request)
            if profiling:
                profiler = Profiler(interval=PROFILING_INTERVAL, async_mode=PROFILING_ASYNC_MODE)
                profiler.start()
                await call_next(request)
                profiler.stop()
                return HTMLResponse(profiler.output_html())

        except Exception as exc:  # pylint: disable=broad-except
            ErrorReporter.report(exc)
            Logger.error(f"Could not profile endpoint: {str(exc)}")

        response = await call_next(request)
        return response

    @staticmethod
    def should_profile(request: Request) -> bool:
        """Return true if the profiling header or query param was passed."""
        return request.headers.get("X-Profile", False) or request.query_params.get("profile", False)

The profiling works -- in that it is added to the app call stack, is enabled, detects code, renders output. However, there is no useful output that I can get. Here are some examples, in html, and speedscope formats:

So what is custom_route_logger you ask? It is the official FastAPI way to subclass the Request object, and is defined async, like this:

    def get_route_handler(self) -> Callable:
        """Use a custom route handler."""
        original_route_handler = super().get_route_handler()

        async def custom_route_handler(request: Request) -> Response:
            request = REDACTEDRequest(request.scope, request.receive)
            return await original_route_handler(request)

        return custom_route_handler

I know the problem comes from this async, and because it is ASGI middleware, I cannot take the async away. But I also cannot profile inside the application as-is.

The goal is to get a single profile of application code on a given api call. My question is, is there some sort of async setup I missed here, or is this an impossible task?

[coneybeare]

I should also note that none of my routes are defined as async, but use the built-in fastapi intelligent async handling. Adding async arbitrarily to a route give results, but is bad for performance if used without taking advantage of async dependencies underneath, as far I am aware.

What do you recommend?

[joerick]

Hmm. So the issue is that the async middleware function results in the request being executed... when exactly? After the profiling has finished? Or in a different async context perhaps? eg. A different thread?

[coneybeare]

If you use def instead of async def, FastAPI runs the request asynchronously on a separate default execution thread to not block IO. So it essentially runs everything async for you under the hood whether you want it or not. Adding async def to the app signals FastAPI to not use that separate default execution thread, which ironically WILL block IO unless the application uses await somewhere down line to free up the thread for handling another request.

[coneybeare]

I don’t know where the issue lies with package’s detection of fast api code that is not living in async def land, but I would be happy to contribute if you think it is a problem with code pathway detection here and can point me in the right direction.

[joerick]

Ah, so a different thread. This will be tricky to track. It might be possible to instrument FastAPI somehow, so that

1. when the request is bounced to another thread, the main thread profiler is stopped
2. over on the background thread, when the request is started to be handled, we start the profiler here
3. once the request is finished, stop the profiler on the background thread
4. restart the profiler on the main thread to capture middlewares up to the profiling middleware.

That sounds like a lot, so pragmatically speaking, it might be better to develop a different pattern for synchronous FastAPI views, where rather than using a middleware, a decorator is used to profile them. I'm pretty sure that decorators would run on the same thread as the function itself.

[coneybeare]

That might work for some use cases, though not sure how to gain access to the underlying request object anymore for inspecting headers, query params. In our use case, we decided to shift to async sqlalchemy calls, so refactored the app and this is no longer an issue. Feel free to close if you would like

[yohann84L]

Hey @coneybeare did you succeed to make your middleware correctly working with pyinstrument ?

[coneybeare]

We did, but only because we shifted to async in our app and made the endpoints async as well.

[yohann84L]

@coneybeare alright I see, thank you!