FastAPI’s asynchronous nature can mask performance bottlenecks, making it look like everything is fast until it suddenly isn’t.
Let’s see what a slow FastAPI endpoint looks like before we profile it.
import asyncio
import time
from fastapi import FastAPI
app = FastAPI()
def slow_operation(duration: int):
"""Simulates a blocking operation."""
time.sleep(duration)
return f"Slept for {duration} seconds"
async def async_slow_operation(duration: int):
"""Simulates an async blocking operation."""
await asyncio.sleep(duration)
return f"Async slept for {duration} seconds"
@app.get("/sync_blocking")
async def sync_blocking_route():
result1 = slow_operation(2) # This blocks the event loop
result2 = await async_slow_operation(1)
return {"sync_result": result1, "async_result": result2}
@app.get("/async_blocking")
async def async_blocking_route():
result1 = await async_slow_operation(2)
result2 = slow_operation(1) # This also blocks the event loop
return {"async_result": result1, "sync_result": result2}
@app.get("/fast")
async def fast_route():
return {"message": "This is fast"}
# To run this:
# 1. Save as main.py
# 2. Install uvicorn and fastapi: pip install uvicorn fastapi
# 3. Run: uvicorn main:app --reload
When you hit /sync_blocking or /async_blocking, your entire FastAPI application will become unresponsive for the duration of the blocking time.sleep() calls. Even though asyncio.sleep is non-blocking, time.sleep is not and will halt the event loop.
To profile this, we’ll use pyinstrument.
First, install it:
pip install pyinstrument
Now, let’s modify our main.py to include pyinstrument profiling. We’ll create a middleware that wraps requests and profiles them.
import asyncio
import time
from fastapi import FastAPI, Request
from pyinstrument import Profiler
from pyinstrument.middleware import ASGIProfilerMiddleware
app = FastAPI()
def slow_operation(duration: int):
"""Simulates a blocking operation."""
time.sleep(duration)
return f"Slept for {duration} seconds"
async def async_slow_operation(duration: int):
"""Simulates an async blocking operation."""
await asyncio.sleep(duration)
return f"Async slept for {duration} seconds"
@app.get("/sync_blocking")
async def sync_blocking_route():
result1 = slow_operation(2) # This blocks the event loop
result2 = await async_slow_operation(1)
return {"sync_result": result1, "async_result": result2}
@app.get("/async_blocking")
async def async_blocking_route():
result1 = await async_slow_operation(2)
result2 = slow_operation(1) # This also blocks the event loop
return {"async_result": result1, "sync_result": result2}
@app.get("/fast")
async def fast_route():
return {"message": "This is fast"}
# --- Pyinstrument Middleware ---
# This middleware will automatically profile all requests
# and print the output to the console.
app.add_middleware(
ASGIProfilerMiddleware,
show_hidden=True, # Show internal Python calls
groups_by_path=True, # Group results by request path
print_methods=["GET", "POST"], # Profile only specific HTTP methods
limit=50 # Show top 50 calls
)
# To run this:
# 1. Save as main.py
# 2. Install uvicorn, fastapi, and pyinstrument: pip install uvicorn fastapi pyinstrument
# 3. Run: uvicorn main:app --reload
Now, when you run uvicorn main:app --reload and hit /sync_blocking or /async_blocking a few times, pyinstrument will automatically print its output to your terminal after each request. You’ll see something like this (simplified):
--- GET /sync_blocking ---
_ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _ . _s
The ASGIProfilerMiddleware intercepts incoming requests and wraps the ASGI application with a Profiler instance. When the response is about to be sent, it stops the profiler and prints the collected data. The _ represents time spent in the middleware itself, and the subsequent lines show functions called and their execution time.
The key takeaway here is that time.sleep() calls, even if they are inside an async def function, will block the entire event loop. This is because async def functions are designed to yield control back to the event loop during await calls, but time.sleep() is a synchronous, blocking operation that prevents the event loop from running other tasks.
To fix this, you should always use await asyncio.sleep() for any I/O-bound or time-waiting operations within an async def function. If you have truly CPU-bound blocking code that you cannot rewrite to be asynchronous, you can run it in a separate thread using asyncio.to_thread() (Python 3.9+) or loop.run_in_executor() (older Python versions).
For example, to fix the sync_blocking route:
@app.get("/sync_blocking_fixed")
async def sync_blocking_route_fixed():
# Use asyncio.to_thread for blocking CPU-bound tasks
result1 = await asyncio.to_thread(slow_operation, 2)
result2 = await async_slow_operation(1)
return {"sync_result": result1, "async_result": result2}
This will run slow_operation in a separate thread pool, allowing the event loop to continue processing other requests while slow_operation executes.
The next thing you’ll likely run into is understanding how to interpret the profiler output for more complex scenarios, such as identifying which database queries or external API calls are taking the longest.