Provide timing data for things FastAPI does outside of user code #9148
-
Is your feature request related to a problem? Please describe. In your average FastAPI application, there's 4 main causes for slowdowns:
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 Describe the solution you'd like Describe alternatives you've considered Additional context |
Beta Was this translation helpful? Give feedback.
Replies: 55 comments 1 reply
-
A couple tangential profiling-related notes that may be of interest to anyone working with "50MBs of JSON"-sized payloads: Click to expand
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 |
Beta Was this translation helpful? Give feedback.
-
Ah, that's interesting, I'd usually just build my own
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.
|
Beta Was this translation helpful? Give feedback.
-
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. |
Beta Was this translation helpful? Give feedback.
-
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) |
Beta Was this translation helpful? Give feedback.
-
Seems like it's actually half
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? |
Beta Was this translation helpful? Give feedback.
-
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) |
Beta Was this translation helpful? Give feedback.
-
I think there is a package called 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. |
Beta Was this translation helpful? Give feedback.
-
Potential problems:
|
Beta Was this translation helpful? Give feedback.
-
Yeah, that's going to be tricky, since you'd probably have to monitor something like
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). |
Beta Was this translation helpful? Give feedback.
-
Also, I can't seem to get your version running properly, I only get the following error message.
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. |
Beta Was this translation helpful? Give feedback.
-
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: |
Beta Was this translation helpful? Give feedback.
-
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() 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. |
Beta Was this translation helpful? Give feedback.
-
@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 |
Beta Was this translation helpful? Give feedback.
-
Don't worry about the FastAPI and other web-framework specifics, the main thing you should know is that we're trying to get profiling results (mainly just total runtime) for specific functions and coroutines, and having multiple concurrent but unrelated async Tasks running on the same thread is leading to some interesting issues.
Disregard that, it's most likely related to how I upgraded my venv from Python36 to Python38; I did some more tests and I have a number of other libraries that are now complaining about version mismatches.
I'll try again with a fresh venv when I get time. If not, it's probably just my environment variables being misconfigured. |
Beta Was this translation helpful? Give feedback.
-
I am also writing here for reference: (along with sumerc/yappi#21) I have done few experiments on python 3.7 for The test branch name is Please send your valuable feedback. |
Beta Was this translation helpful? Give feedback.
-
It was a typo left for debugging something... Ok. I think you can also continue testing in parallel and I will be informing you after implementing the filtering. Maybe also do CPU time testing...etc.. not sure about use cases. Then before release: I need to make sure all code works for all Python versions and write more and more tests. But meanwhile hopefully you can start integrating yappi into your workflow :) Thanks again guys! |
Beta Was this translation helpful? Give feedback.
-
Ok. This will hopefully be my final update: Anyway, I will be finalizing the tests and hopefully will be releasing a new version which includes lots of new, exciting stuff. Looking forward to your latest feedback and use cases in FastAPI, too, of course. |
Beta Was this translation helpful? Give feedback.
-
looking forward to test your latest improvments but so far even before the hashtable it was perfect ! thanks a lot @sumerc |
Beta Was this translation helpful? Give feedback.
-
What if I were to leave the profiler running on a test server for several days or weeks, wouldn't the inability to "garbage collect" old profiling data cause memory or performance issues? |
Beta Was this translation helpful? Give feedback.
-
I am not expecting performance issues, but we sure might have some memory issues. Maybe it would be better to implement this, but let's postpone as currently there is lots of code written for this feature and I really do not want to complicate things more. And for your scenario: you can always call clear_stats() at 10000 request or in some specific interval like per-day. If the server is running several days/weeks I think having a few invalid profile calculations for couple of requests might not be so important after all. |
Beta Was this translation helpful? Give feedback.
-
Guys! Thank you for all your help on this. Today, I have released a new version of Yappi(1.2.1). You can hopefully use it via installing from pip. I have updated the docs as well and written a bit more about coroutine profiling here: https://github.com/sumerc/yappi/blob/coroutine-profiling/doc/coroutine-profiling.md. Please send me if you find any problems/inconsistencies with the new release. And for the future: I am open to any new suggestions on profiling async. code. Please do not hesitate to discuss/ask anything you think might help you making the code faster. I will be adding your names on THANKS, that is all I can do at this time:) |
Beta Was this translation helpful? Give feedback.
-
This is fantastic! Way to set Yappi appart from any other python profiler, even the official ones. I also need to thank you for all the time and effort you've put into supporting this idea I was just throwing out there as a possible feature to integrate into the framework. I didn't even think it was possible to profile coroutines in Python, and as it turns out, I was right... ...but now, only a month later, thanks to you, it's now possible. So thank you, @sumerc! And here's to yappi becoming the go-to profiler for all async programs! |
Beta Was this translation helpful? Give feedback.
-
So I'm getting pretty good results with this test middleware and the following config for FastAPI: from fastapi import FastAPI
app = FastAPI(debug=DEBUG, openapi_prefix=PATH_PREFIX)
import fastapi
import starlette.responses
import sqlalchemy.engine.base
app.add_middleware(ServerTimingMiddleware, calls_to_track={
# All steps of the generated fastapi.routing.get_request_handler app
"1deps": fastapi.routing.solve_dependencies.__qualname__, # `Depends` execution
#"2endpoint": fastapi.routing.get_request_handler.?????.__qualname__,
"3valid": fastapi.routing.ModelField.validate.__qualname__, # Pydantic model validation
"4encode": fastapi.encoders.jsonable_encoder.__qualname__, # JSON encoding
#"5render": starlette.responses.Response.render.__qualname__, # Respnse (JSON) rendering
# Extra measurements
"db_exec": sqlalchemy.engine.base.Engine.execute.__qualname__,
#"db_fetch": sqlalchemy.engine.ResultProxy.fetchone.__qualname__,
}) I still can't figure how (generically) to get timing for the endpoint and response rendering execution. Response rendering is a problem because there's no easy way to connect Meanwhile, endpoint duration is a problem because the endpoint executor doesn't have a qualified name, it's executed as part of the That means there's no single named function I can profile to get the endpoint execution time. Unless we extract those lines into some |
Beta Was this translation helpful? Give feedback.
-
Thanks everyone for all the conversation here! 👏 🤓 I'm amazed by the value I see you generated here with your combinations of ideas. 😮 ✨ Thanks a lot @sumerc for all the effort you put into adding support for these async tools. 🚀 💪 🎉 Did anyone of you publish the middleware as a package? I see @dmontagu 's I tried @sm-Fifteen 's implementation from the comment there and I got stats in the developer tools in the browser. That's awesome! 🚀 I think that deserves existing as a published ASGI middleware package. Maybe@sm-Fifteen could publish it, or @dmontagu could include it in Also, trying it locally I had to change the line: response['headers'].append(["server-timing", b','.join(server_timing)]) to response['headers'].append([b"server-timing", b','.join(server_timing)]) ( @sm-Fifteen about timing the endpoint alone, I see the value in this and in being able to time just the endpoint duration. Would you like to send a PR putting that in a separate function? |
Beta Was this translation helpful? Give feedback.
-
Thanks! 😄 I'm a bit impressed myself at how well this all turned out.
Yeah, I probably missed a few things here or there. Like I said in that other post, this was more meant as a WIP proof-of-concept, and I was worried about a few remaining yappi issues (namely: "How should the profiler free memory?", "What's a reliable way to tell yappi to profile a specific function?") (also raised by dmontagu) causing problems so I haven't touched it much since. I can probably just polish up what's there, add a memory threshold where the middleware just wipes the profiler memory so it doesn't inflate until Python goes OOM, add a README listing the caveats and publish it.
Well,, if you're open to it, then I might as well. It's certainly going to be easier than the crazy solution I was considering, where I somehow time |
Beta Was this translation helpful? Give feedback.
-
I think that we now have a clear way to solve this and all the pieces in place on the FastAPI side. The only piece missing is a third-party middleware (or just these snippets properly configured). But as that would be on a third-party package, I think we can close this issue on the FastAPI side, right @sm-Fifteen ? |
Beta Was this translation helpful? Give feedback.
-
@tiangolo: Pretty much. I'm going to release this as a proper middleware in the near future; I've mainly been holding off on it because the current way of determining if a function in the profiler's data matches one of the targeted ones is currently incorrect (see sumerc/yappi#22) due to a few implementation details in CPython that I wouldn't want to couple a simple ASGI middleware with. The next release of Yappi addresses this by letting users match functions by their descriptors instead of their name (see sumerc/yappi#41), so once that lands, I'll probably make PR to add it in the FastAPI documentation or something like that. Whether you would rather keep this issue open until then, or consider the problem generally solved is up to you. |
Beta Was this translation helpful? Give feedback.
-
Is it possible to use this solution to time Starlette middlewares themselves, given that this is itself a middleware? I am currently evaluating APM solutions (and their respective middlewares), and it would be very helpful if I could get some idea of the performance impact each one is having. |
Beta Was this translation helpful? Give feedback.
-
@acnebs: As long as they're registered to run after the profiling middleware (because the context variables wouldn't be registered otherwise), maybe, although making sure that only the target middleware gets timed and not the rest of the application (since middleware have to call the next ASGI callable with the scope as part of their activity, meaninng they are always part of the application's callstack) might prove a bit tricky. The middleware I have right now can only return the end-to-end execution duration for the functions specified and I don't really know how complex I want to make that middleware. |
Beta Was this translation helpful? Give feedback.
-
Any updates on this? |
Beta Was this translation helpful? Give feedback.
@acnebs: As long as they're registered to run after the profiling middleware (because the context variables wouldn't be registered otherwise), maybe, although making sure that only the target middleware gets timed and not the rest of the application (since middleware have to call the next ASGI callable with the scope as part of their activity, meaninng they are always part of the application's callstack) might prove a bit tricky. The middleware I have right now can only return the end-to-end execution duration for the functions specified and I don't really know how complex I want to make that middleware.