Provide timing data for things FastAPI does outside of user code

[sm-Fifteen]

Is your feature request related to a problem? Please describe.
I currently find myself using FastAPI as an API frontend for a database running queries of varying levels of complexity that usually return fairly large quantities of data. The problem I have is that, when attempting to figure out why an API request is taking time to respond, there's a lot going on outside of what fencing the code inside your route with the usual time_start = time.time(), time_delta = time.time() - time_start won't tell you.

In your average FastAPI application, there's 4 main causes for slowdowns:

• Endpoint code running (app)
• Waiting for the database (io)
• Data validation (pydantic)
• Data serialization (json/ujson)

Of those 4, only the first two are actually part of the user code, the other two are handled behind the scenes by FastAPI. If I'm testing a route that's returning 50MBs of JSON (for whatever reason), it's actually rather tricky to determine whether switching from json to ujson or orjson will have any performance benefit or if the slowdown is coming from Pydantic choking on the sheer amount of data being fed to it or the database being slow.

Describe the solution you'd like
Given FastAPI is performing operations outside of what the user can observe or measure, it should probably expose timing data for those things in some way (especially validation and serialization, since I doubt routing is going to factor a lot in the processing time). I don't know how the implementation should go, though, given any middleware is only going to receive a Starlette Response object and FastAPI probably shouldn't be doing this sort of thing automatically anymore than it does with CORS. The Response object could probably be extended in some way to contain some sort of timing dict, though that's sure to cause all sorts of compatibility issues, so I don't know whether that can be done without some upstream work with Starlette.

Describe alternatives you've considered
I was initially trying to write a middleware for this, but python's own cProfile is limited to text file export, so processing the data in Python becomes an extra hurdle, if the format is even stable enough for that. Without using a profiler, ASGI middlewares simply don't have access to timing information for the app besides the total time spent awaiting the callable.

Additional context
The recently introduced Server-Timing HTTP header seems like a perfect way to push coarse profiling information to make debugging those cases somewhat easier, especially given how it's supported in the Chrome devtools and that Firefox support for it is just around the corner. That's probably beyond the scope of that issue, though.

[dmontagu]

A couple tangential profiling-related notes that may be of interest to anyone working with "50MBs of JSON"-sized payloads:

Click to expand

• Serialization may also involve two (potentially very costly!) steps: 1) if specifying a response_model, where the returned data is parsed into the response_model, and 2) in all cases unless you return a Response directly, where fastapi.encoders.jsonable_encoder is used to convert your output to json.
  • For payloads with long lists or dicts with many keys this function call is not cheap, and unless you return a Response or one of its subclasses from your endpoint, in most cases, the cost of jsonable_encoder will probably dwarf the call to json.dumps or faster alternatives from other packages.
• For faster creation of pydantic model instances, consider using BaseModel.construct if you know the input data doesn't require parsing (e.g., whenever you perform the instantiation yourself in a type-safe way, rather than relying on fastapi's parsing machinery).
  • I profiled this method at ~30-40x faster than calls to BaseModel.__init__, even for relatively small payloads.
  • The API is a little awkward in pydantic v0.32.2 since you have to pass the values as a dict (and have to specify the fields set), but starting in v1 it has the same API as the __init__ calls and is even type-checked by the pydantic mypy plugin (a good reason for FastAPI to update to pydantic v1 as soon as possible!).

---

Addressing the main point brought up in this issue, I think it might be worth looking into yappi -- if you look at the docs for the get_func_stats function and the YFuncStat class, it looks like it should be relatively easy to package up the profiling results inside an ASGI middleware. (Also, for what it's worth, it has built-in support in PyCharm.)

I'm not very familiar with the Server-Timing header, but based on a quick skim of the linked docs, it seems that such a yappi ASGI middleware could return Server-Timing headers for each of its YFuncStat instances, presumably with some (configurable) filtering and formatting. (Obviously it could also just log the results to the console.)

[sm-Fifteen]

A couple tangential profiling-related notes that may be of interest to anyone working with "50MBs of JSON"-sized payloads:

Ah, that's interesting, I'd usually just build my own RawJSONResponse class and handle json conversion on my own so I could bypass Pydantic entirely, but this is certainly much cleaner if you trust your input source.

Addressing the main point brought up in this issue, I think it might be worth looking into yappi -- if you look at the docs for the get_func_stats function and the YFuncStat class, it looks like it should be relatively easy to package up the profiling results inside an ASGI middleware. (Also, for what it's worth, it has built-in support in PyCharm.)

I'm not very familiar with the Server-Timing header, but based on a quick skim of the linked docs, it seems that such a yappi ASGI middleware could return Server-Timing headers for each of its YFuncStat instances, presumably with some (configurable) filtering and formatting. (Obviously it could also just log the results to the console.)

Thanks for pointing out yappi. I've tried the middleware solution with it, and while it's working well enough, it runs into the issue where, since profiling is global, if a route is called while another one is running, the profiler gets confused and the resulting profiling data will be incorrect or missing.

from starlette.middleware.base import BaseHTTPMiddleware
from starlette.responses import Response
from starlette.requests import Request

import fastapi
import json
import sqlalchemy

import yappi

class BenchMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next) -> Response:
        yappi.start()
        response = await call_next(request)
        yappi.stop()

        #yappi.get_func_stats().sort('ttot', sort_order="desc").print_all() # All time

        db_exec_time = yappi.get_func_stats(dict(name=sqlalchemy.engine.base.Engine.execute.__qualname__))
        #db_fetch_time = yappi.get_func_stats(dict(name=sqlalchemy.engine.result.ResultProxy.fetchone.__qualname__))
        pydantic_time = yappi.get_func_stats(dict(name=fastapi.routing.serialize_response.__qualname__))
        render_time = yappi.get_func_stats(dict(name=response.render.__qualname__))

        server_timing = []

        if not db_exec_time.empty():
            server_timing.append(f"db_exec;dur={(db_exec_time.pop().ttot * 1000):.3f}")

        if not pydantic_time.empty():
            server_timing.append(f"pydantic;dur={(pydantic_time.pop().ttot * 1000):.3f}")

        if not render_time.empty():
            server_timing.append(f"render;dur={(render_time.pop().ttot * 1000):.3f}")

        yappi.clear_stats()
        response.headers["Server-Timing"] = ','.join(server_timing)
        return response

Because of that, I doubt that can be "correctly realized" on an async framework like FastAPI using a regular profiler, since I'd ideally want to leave this sort of performance collection online to facilitate performance analysis in real-world use cases.

Server-Timing is working as I'd hoped, though.

[dmontagu]

Haha, that's some heavy pydantic!

Yappi is able to track threads appropriately; I'm wondering if there is a way to use async contextvars in python 3.7 to achieve similar functionality. I'll look into it.

[dmontagu]

Aha! It looks like you can override the context id callback with yappi!

See here: https://github.com/sumerc/yappi/blob/master/yappi.py#L938

I think we could use a contextvar for this and should be able to get proper per-request profiling! (In Python >=3.7)

[sm-Fifteen]

Haha, that's some heavy pydantic!

Seems like it's actually half jsonable_encoder and half Field.validate. But yeah, it's 6 or so sets of 9600 datapoints each, separated in arrays of 100 floats keyed by ISO8601 datetime. It's a good stress test, I'd say, even if common sense would advise to just return this as a CSV instead.

Aha! It looks like you can override the context id callback with yappi!

See here: https://github.com/sumerc/yappi/blob/master/yappi.py#L938

I think we could use a contextvar for this and should be able to get proper per-request profiling! (In Python >=3.7)

You seem to have a pretty clear idea of how that could be done. I haven't had the occasion to use contextvars yet, so could you show me how you would go about doing that?

[sm-Fifteen]

I looked into it a little, and I'm assuming you mean something along those lines?

import contextvars

profiler_ctx_id = contextvars.ContextVar('profiler_ctx_id')

yappi.set_context_id_callback(lambda: profiler_ctx_id.get())

class BenchMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next) -> Response:
        ctx_token = profiler_ctx_id.set(id(asyncio.current_task())) # Set unique id in context

        yappi.start()
        response = await call_next(request)
        yappi.stop()

(Guess I should update to python 3.7 or 3.8, since the contextvars backport for 3.6 doesn't work with asyncio)

[dmontagu]

I think there is a package called aiocontextvars which works with python 3.6.

This is what I have in mind:

from contextvars import ContextVar
from typing import Dict

import yappi
from starlette.middleware.base import BaseHTTPMiddleware
from starlette.requests import Request
from starlette.responses import Response
from starlette.types import ASGIApp
from yappi import YFuncStats

yappi_request_id = ContextVar('yappi_request_id')
yappi_request_id.set(-1)


def get_context_id() -> int:
    try:
        return yappi_request_id.get()
    except LookupError:
        return -2


yappi.set_context_id_callback(get_context_id)


class BenchMiddleware(BaseHTTPMiddleware):
    def __init__(self, app: ASGIApp, calls_to_track: Dict[str, str]) -> None:
        self.calls_to_track = calls_to_track
        super().__init__(app, None)

    async def dispatch(self, request: Request, call_next) -> Response:
        ctx_id = id(request)
        yappi_request_id.set(ctx_id)
        response = await call_next(request)

        tracked_stats: Dict[str, YFuncStats] = {}
        for name, call_to_track in self.calls_to_track.items():
            tracked_stats[name] = yappi.get_func_stats({"name": call_to_track, "ctx_id": ctx_id})

        server_timing = []
        for name, stats in tracked_stats.items():
            if not stats.empty():
                server_timing.append(f"{name};dur={(stats.pop().ttot * 1000):.3f}")
        if server_timing:
            response.headers["Server-Timing"] = ','.join(server_timing)
        return response


# ######################
# ##### Usage test #####
# ######################
import asyncio

import fastapi
import sqlalchemy
from httpx import AsyncClient
from fastapi import FastAPI

yappi.start()  # If you don't start yappi, stats.empty() will always be true
app = FastAPI()


@app.get("/")
async def context_id_endpoint() -> int:
    await asyncio.sleep(1)
    return get_context_id()


track: Dict[str, str] = {
    "db_exec": sqlalchemy.engine.base.Engine.execute.__qualname__,
    "pydantic": fastapi.routing.serialize_response.__qualname__,
    "render": Response.render.__qualname__,
    "endpoint": context_id_endpoint.__qualname__
}
app.add_middleware(BenchMiddleware, calls_to_track=track)


async def main():
    client = AsyncClient(app=app, )
    tasks = [client.get("http://www.example.org/") for _ in range(5)]
    resps = await asyncio.gather(*tasks)
    for resp in resps:
        print(f"Request ID: {resp.json()}")
        print(f"Server Timing: {resp.headers.get('server-timing')}")
        print("-----")


if __name__ == '__main__':
    asyncio.run(main())

"""
Request ID: 4451087568
Server Timing: pydantic;dur=0.980,render;dur=0.003,endpoint;dur=0.248
-----
Request ID: 4451120784
Server Timing: pydantic;dur=0.083,render;dur=0.003,endpoint;dur=0.227
-----
Request ID: 4451140944
Server Timing: pydantic;dur=0.057,render;dur=0.002,endpoint;dur=0.296
-----
Request ID: 4451161168
Server Timing: pydantic;dur=0.048,render;dur=0.003,endpoint;dur=0.196
-----
Request ID: 4451169104
Server Timing: pydantic;dur=0.047,render;dur=0.004,endpoint;dur=0.192
-----
"""

There is a little more tweaking to do here, but I wanted to share progress now.

[dmontagu]

Potential problems:

1. I can't figure out how to track time spent awaiting async calls -- clearly that isn't showing up in the printouts of the endpoint duration. Using yappi.set_clock_type("wall") also doesn't help with await calls.

   This shouldn't matter too much if the goal is just to find cpu bottlenecks (e.g., related to serialization), and it shouldn't be a problem if you use def endpoints to achieve non-blocking IO, but it means that you can't get wall-time profiling for asyncio-based io. This seems kind of unfortunate for an ASGI middleware.

2. It would be nice if there was an easier way to track stats by module and function name; there is a way to filter by the "full_name", and to strip dirs from the filenames, but it annoyingly includes line numbers. Maybe that's fine for now, or maybe there is an easy way to just pass the callable itself to the middleware, and use the yappi function directly to determine the full_name.

[sm-Fifteen]

1. I can't figure out how to track time spent awaiting async calls -- clearly that isn't showing up in the printouts of the endpoint duration. Using `yappi.set_clock_type("wall")` also doesn't help with `await` calls.

Yeah, that's going to be tricky, since you'd probably have to monitor something like Task._step() or whatever the event loop stays parked in when it has nothing to do (if that's even possible). I looked it up and asyncio doesn't offer any sort of hook to keep track of how much time a task has spent running or suspended (or blocked from resuming because the event loop is busy). A lot of existing profilers "work" with async, but they don't neccesarily make it easy to get that sort of metric.

2\. It would be nice if there was an easier way to track stats by module and function name; there is a way to filter by the "full_name", and to strip dirs from the filenames, but it annoyingly includes line numbers. Maybe that's fine for now, or maybe there is an easy way to just pass the _callable itself_ to the middleware, and use the yappi function directly to determine the full_name.

I've seen a dir-stripping method in their doc, so that part shouldn't be an issue. Regarding gearing the middleware to take callables as parameters... yeah, that's not a bad idea. Those functions have enough introspection data to make it possible to derive what to feed the profiler to get info on them. Your other concerns would probably only affect the result of printing the complete output, though, not the headers I was planning to use, so that shouldn't be too much of a problem (although that could also be logged somewhere else, I don't know).

[sm-Fifteen]

Also, I can't seem to get your version running properly, I only get the following error message.

[*] [yappi-err] context id callback returned non-integer
Request ID: 2466563236480
Server Timing: None
-----
Request ID: 2466563267168
Server Timing: None
-----
Request ID: 2466563273776
Server Timing: None
-----
Request ID: 2466563274736
Server Timing: None
-----
Request ID: 2466563275696
Server Timing: None
-----

https://github.com/sumerc/yappi/blob/afb2cffa815bae84c649fee43ea2b63419716a7a/_yappi.c#L227-L242

I'm not entirely sure what's causing this, no exception seems to even be thrown and debugging C modules is not as straightforward as pure Python.

[sumerc]

Hello everyone, I am the author of yappi and as I said in the issue opened by @dmontagu sumerc/yappi#21 , I would be more than happy to try my best helping you guys regarding profiling async. code.

I have not been able to digest all the information in this thread but if you need help please do not hesitate.

For the last question:
[*] [yappi-err] context id callback returned non-integer
This error means the context_id_callback returns a value that fails PyLong_AsLong() like you have suggested. Is it possible you return None or any other object other than an integer in that function somehow?

[sumerc]

And regarding the other problem(wall time is not being correct). IIRC, this was something we have solved for gevent library. See this code here: https://github.com/ajdavis/GreenletProfiler/blob/700349864a4f368a8a73a2a60f048c2e818d7cea/_vendorized_yappi/_yappi.c#L577

_pause_ctx()
_resume_ctx()

So, every time a ctx switch occurs, meaning context_id returned a different value, we simply pause_ctx and when it is resumed we call _resume_ctx which updates the internal call_stack time values by the factor of pause duration which should probably give correct results.

Please tell me this was your problem. I might have misunderstood the root of the problem here.

[dmontagu]

@sumerc Thanks for all the help! This may well solve the problem; I'll try it out.

@sm-Fifteen I'm running it in Python 3.7; is that a difference? Maybe try using aiocontextvars instead of contextvars in python 3.6?