Add Server-Timing headers to all API endpoints for per-request latency breakdown

Instrument every API endpoint with Server-Timing headers so sub-operation
durations are visible in browser DevTools Network tab. Also adds Grafana
dashboard panels for per-endpoint latency comparison (p50/p95 timeseries
and p95 ranking bar gauge).
This commit is contained in:
Viktor Barzin 2026-02-23 21:30:51 +00:00
parent 35f1987ac1
commit 2357722e80
No known key found for this signature in database
GPG key ID: 0EB088298288D958
4 changed files with 271 additions and 5 deletions

View file

@ -20,7 +20,7 @@ from api.metrics_guard import MetricsGuardMiddleware
from api.security_headers import SecurityHeadersMiddleware
from api.origin_validator import OriginValidatorMiddleware
from dotenv import load_dotenv
from fastapi import Depends, FastAPI, HTTPException, Query
from fastapi import Depends, FastAPI, HTTPException, Query, Response
from fastapi.responses import JSONResponse, StreamingResponse
from pydantic import BaseModel
from starlette.requests import Request
@ -151,9 +151,11 @@ async def unhandled_exception_handler(request: Request, exc: Exception) -> JSONR
@app.get("/api/status")
async def get_status() -> dict[str, str | None]:
async def get_status(response: Response) -> dict[str, str | None]:
t0 = time.monotonic()
repository = ListingRepository(engine)
last_updated = repository.get_last_updated()
response.headers["Server-Timing"] = f"db_query;dur={(time.monotonic() - t0) * 1000:.1f}"
return {
"status": "OK",
"last_updated": last_updated.isoformat() if last_updated else None,
@ -163,12 +165,15 @@ async def get_status() -> dict[str, str | None]:
@app.get("/api/listing")
async def get_listing(
user: Annotated[User, Depends(get_current_user)],
response: Response,
limit: int = 5,
) -> dict[str, list]:
"""Get listings from the database."""
limit = min(limit, _rate_limit_config.listing_limit_cap)
repository = ListingRepository(engine)
t0 = time.monotonic()
result = await listing_service.get_listings(repository, limit=limit)
response.headers["Server-Timing"] = f"get_listings;dur={(time.monotonic() - t0) * 1000:.1f}"
logger.info(f"Fetched {result.total_count} listings for {user.email}")
return {"listings": result.listings}
@ -177,23 +182,30 @@ async def get_listing(
async def get_listing_geojson(
user: Annotated[User, Depends(get_current_user)],
query_parameters: Annotated[QueryParameters, Depends(get_query_parameters)],
response: Response,
limit: int | None = None,
decision_filter: str = "all",
) -> dict:
"""Get listings as GeoJSON for map display."""
timings: list[str] = []
t0_total = time.monotonic()
if limit is not None:
limit = min(limit, _rate_limit_config.geojson_limit_cap)
else:
limit = _rate_limit_config.geojson_limit_cap
repository = ListingRepository(engine)
t0 = time.monotonic()
result = await export_service.export_to_geojson(
repository,
query_parameters=query_parameters,
limit=limit,
)
timings.append(f"export_geojson;dur={(time.monotonic() - t0) * 1000:.1f}")
# Apply decision filtering
if decision_filter != "everything":
t0 = time.monotonic()
user_id = _get_user_id_safe(user.email)
if user_id is not None:
decision_repo = DecisionRepository(engine)
@ -208,7 +220,10 @@ async def get_listing_geojson(
)
]
result.data["features"] = features
timings.append(f"decision_filter;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return result.data
@ -525,7 +540,12 @@ async def stream_listing_geojson(
timings: list[str] = []
# Build POI distances lookup if requested
poi_distances_lookup = _build_poi_distances_lookup(user.email, query_parameters.listing_type) if include_poi_distances else None
if include_poi_distances:
t0 = time.monotonic()
poi_distances_lookup = _build_poi_distances_lookup(user.email, query_parameters.listing_type)
timings.append(f"poi_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
else:
poi_distances_lookup = None
t0 = time.monotonic()
cached_count = get_cached_count(query_parameters)
@ -533,7 +553,10 @@ async def stream_listing_geojson(
if cached_count is not None and cached_count > 0 and not include_poi_distances:
app_metrics.geojson_cache_operations.add(1, {"result": "hit"})
t0 = time.monotonic()
stale = is_cache_stale(query_parameters)
timings.append(f"stale_check;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append('source;desc="cache"')
if stale:
app_metrics.cache_stale_serves_total.add(1)
# Fire-and-forget background repopulation
@ -549,6 +572,7 @@ async def stream_listing_geojson(
)
else:
app_metrics.geojson_cache_operations.add(1, {"result": "miss"})
timings.append('source;desc="db"')
generator = _instrumented_stream(
_stream_from_db(
query_parameters, batch_size, limit, poi_distances_lookup,
@ -696,9 +720,13 @@ class ListingDetailResponse(BaseModel):
async def get_listing_detail(
user: Annotated[User, Depends(get_current_user)],
listing_id: int,
response: Response,
listing_type: str = Query(default="RENT"),
) -> ListingDetailResponse:
"""Get detailed information for a single listing."""
timings: list[str] = []
t0_total = time.monotonic()
repository = ListingRepository(engine)
lt = ListingType(listing_type)
t_step = time.monotonic()
@ -708,10 +736,12 @@ async def get_listing_detail(
app_metrics.listing_detail_step_duration_seconds.record(
time.monotonic() - t_step, {"step": "fetch_listing"}
)
timings.append(f"fetch_listing;dur={(time.monotonic() - t_step) * 1000:.1f}")
if not listings:
raise HTTPException(status_code=404, detail="Listing not found")
listing = listings[0]
t_parse = time.monotonic()
additional_info = listing.additional_info or {}
property_info = additional_info.get("property", {})
@ -782,6 +812,7 @@ async def get_listing_detail(
furnish_type_val = str(ft)
# Load user's decision for this listing
timings.append(f"parse_detail;dur={(time.monotonic() - t_parse) * 1000:.1f}")
t_step = time.monotonic()
decision_val: str | None = None
user_id = _get_user_id_safe(user.email)
@ -795,6 +826,7 @@ async def get_listing_detail(
app_metrics.listing_detail_step_duration_seconds.record(
time.monotonic() - t_step, {"step": "load_decision"}
)
timings.append(f"load_decision;dur={(time.monotonic() - t_step) * 1000:.1f}")
# Load POI distances
t_step = time.monotonic()
@ -818,6 +850,9 @@ async def get_listing_detail(
app_metrics.listing_detail_step_duration_seconds.record(
time.monotonic() - t_step, {"step": "load_poi_distances"}
)
timings.append(f"load_poi_distances;dur={(time.monotonic() - t_step) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return ListingDetailResponse(
id=listing.id,

View file

@ -1,7 +1,8 @@
import logging
import time
from typing import Annotated
from fastapi import APIRouter, Depends, HTTPException, Query
from fastapi import APIRouter, Depends, HTTPException, Query, Response
from pydantic import BaseModel, Field
from api.auth import User, get_current_user
@ -55,11 +56,17 @@ async def set_decision(
user: Annotated[User, Depends(get_current_user)],
listing_id: int,
body: SetDecisionRequest,
response: Response,
) -> DecisionResponse:
"""Set or update a like/dislike decision for a listing."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = DecisionRepository(engine)
try:
t0 = time.monotonic()
result = decision_service.set_decision(
repo,
user_id=user_id,
@ -67,19 +74,31 @@ async def set_decision(
listing_type=body.listing_type,
decision=body.decision,
)
timings.append(f"upsert;dur={(time.monotonic() - t0) * 1000:.1f}")
except ValueError as e:
raise HTTPException(status_code=400, detail=str(e))
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return _to_response(result)
@decision_router.get("", response_model=list[DecisionResponse])
async def get_decisions(
user: Annotated[User, Depends(get_current_user)],
response: Response,
) -> list[DecisionResponse]:
"""Get all decisions for the current user."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = DecisionRepository(engine)
t0 = time.monotonic()
decisions = decision_service.get_user_decisions(repo, user_id)
timings.append(f"fetch;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return [_to_response(d) for d in decisions]
@ -87,17 +106,26 @@ async def get_decisions(
async def delete_decision(
user: Annotated[User, Depends(get_current_user)],
listing_id: int,
response: Response,
listing_type: str = Query(..., description="RENT or BUY"),
) -> dict[str, bool]:
"""Remove a decision (un-like/un-dislike)."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = DecisionRepository(engine)
try:
t0 = time.monotonic()
deleted = decision_service.remove_decision(
repo, user_id, listing_id, listing_type
)
timings.append(f"delete;dur={(time.monotonic() - t0) * 1000:.1f}")
except ValueError as e:
raise HTTPException(status_code=400, detail=str(e))
if not deleted:
raise HTTPException(status_code=404, detail="Decision not found")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return {"success": True}

View file

@ -1,7 +1,8 @@
import logging
import time
from typing import Annotated
from fastapi import APIRouter, Depends, HTTPException
from fastapi import APIRouter, Depends, HTTPException, Response
from pydantic import BaseModel, Field
from api.auth import User, get_current_user
@ -79,11 +80,20 @@ def _poi_to_response(poi: "poi_service.PointOfInterest") -> POIResponse:
@poi_router.get("", response_model=list[POIResponse])
async def list_pois(
user: Annotated[User, Depends(get_current_user)],
response: Response,
) -> list[POIResponse]:
"""List all POIs for the current user."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
pois = poi_service.get_user_pois(repo, user_id)
timings.append(f"fetch_pois;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return [_poi_to_response(p) for p in pois]
@ -91,10 +101,16 @@ async def list_pois(
async def create_poi(
user: Annotated[User, Depends(get_current_user)],
body: CreatePOIRequest,
response: Response,
) -> POIResponse:
"""Create a new POI."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
result = poi_service.create_poi(
repo,
user_id=user_id,
@ -103,6 +119,9 @@ async def create_poi(
latitude=body.latitude,
longitude=body.longitude,
)
timings.append(f"create;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return _poi_to_response(result.poi)
@ -111,10 +130,16 @@ async def update_poi(
user: Annotated[User, Depends(get_current_user)],
poi_id: int,
body: UpdatePOIRequest,
response: Response,
) -> POIResponse:
"""Update an existing POI."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
result = poi_service.update_poi(
repo,
poi_id=poi_id,
@ -124,8 +149,11 @@ async def update_poi(
latitude=body.latitude,
longitude=body.longitude,
)
timings.append(f"update;dur={(time.monotonic() - t0) * 1000:.1f}")
if result is None:
raise HTTPException(status_code=404, detail="POI not found")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return _poi_to_response(result.poi)
@ -133,13 +161,22 @@ async def update_poi(
async def delete_poi(
user: Annotated[User, Depends(get_current_user)],
poi_id: int,
response: Response,
) -> dict[str, bool]:
"""Delete a POI and its associated distances."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
deleted = poi_service.delete_poi(repo, poi_id, user_id)
timings.append(f"delete;dur={(time.monotonic() - t0) * 1000:.1f}")
if not deleted:
raise HTTPException(status_code=404, detail="POI not found")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return {"success": True}
@ -148,16 +185,24 @@ async def calculate_distances(
user: Annotated[User, Depends(get_current_user)],
poi_id: int,
body: CalculateRequest,
response: Response,
) -> dict[str, str]:
"""Trigger distance calculation for a POI."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
# Verify POI exists and belongs to user
t0 = time.monotonic()
poi = poi_service.get_poi(repo, poi_id)
if poi is None or poi.user_id != user_id:
raise HTTPException(status_code=404, detail="POI not found")
timings.append(f"verify_poi;dur={(time.monotonic() - t0) * 1000:.1f}")
t0 = time.monotonic()
result = poi_service.trigger_calculation(
poi_id=poi_id,
travel_modes=body.travel_modes,
@ -165,33 +210,51 @@ async def calculate_distances(
user_email=user.email,
listing_ids=body.listing_ids,
)
timings.append(f"trigger;dur={(time.monotonic() - t0) * 1000:.1f}")
if result.task_id:
task_service.add_task_for_user(user.email, result.task_id)
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return {"task_id": result.task_id or "", "message": result.message}
@poi_router.get("/distances/bulk")
async def get_bulk_distances(
user: Annotated[User, Depends(get_current_user)],
response: Response,
listing_type: ListingType = ListingType.RENT,
) -> dict[int, list[POIDistanceResponse]]:
"""Get all POI distances for the current user, keyed by listing ID."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
pois = {p.id: p for p in poi_service.get_user_pois(repo, user_id)}
timings.append(f"fetch_pois;dur={(time.monotonic() - t0) * 1000:.1f}")
if not pois:
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return {}
from repositories.listing_repository import ListingRepository
from database import engine as db_engine
listing_repo = ListingRepository(db_engine)
t0 = time.monotonic()
all_ids = list(listing_repo.get_listing_ids(listing_type))
timings.append(f"fetch_ids;dur={(time.monotonic() - t0) * 1000:.1f}")
if not all_ids:
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return {}
t0 = time.monotonic()
distances = repo.get_distances_for_listings(all_ids, listing_type, user_id)
timings.append(f"fetch_distances;dur={(time.monotonic() - t0) * 1000:.1f}")
result: dict[int, list[POIDistanceResponse]] = {}
for d in distances:
@ -205,6 +268,8 @@ async def get_bulk_distances(
distance_meters=d.distance_meters,
)
)
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return result
@ -212,19 +277,30 @@ async def get_bulk_distances(
async def get_distances(
user: Annotated[User, Depends(get_current_user)],
listing_id: int,
response: Response,
listing_type: ListingType = ListingType.RENT,
) -> list[POIDistanceResponse]:
"""Get POI distances for a specific listing."""
timings: list[str] = []
t0_total = time.monotonic()
t0 = time.monotonic()
user_id = _get_user_id(user)
timings.append(f"user_lookup;dur={(time.monotonic() - t0) * 1000:.1f}")
repo = POIRepository(engine)
t0 = time.monotonic()
poi_repo_pois = {
p.id: p for p in poi_service.get_user_pois(repo, user_id)
}
timings.append(f"fetch_pois;dur={(time.monotonic() - t0) * 1000:.1f}")
t0 = time.monotonic()
distances = poi_service.get_distances_for_listing(
repo, listing_id, listing_type, user_id
)
timings.append(f"fetch_distances;dur={(time.monotonic() - t0) * 1000:.1f}")
timings.append(f"total;dur={(time.monotonic() - t0_total) * 1000:.1f}")
response.headers["Server-Timing"] = ", ".join(timings)
return [
POIDistanceResponse(
poi_id=d.poi_id,

View file

@ -3531,6 +3531,133 @@
],
"title": "Listing Detail Load Time",
"type": "stat"
},
{
"collapsed": false,
"gridPos": { "h": 1, "w": 24, "x": 0, "y": 115 },
"id": 250,
"panels": [],
"title": "Per-Endpoint Latency Comparison",
"type": "row"
},
{
"datasource": { "type": "prometheus", "uid": "PBFA97CFB590B2093" },
"description": "p50 and p95 request latency per endpoint",
"fieldConfig": {
"defaults": {
"custom": {
"axisBorderShow": false,
"axisCenteredZero": false,
"axisColorMode": "text",
"axisLabel": "",
"axisPlacement": "auto",
"barAlignment": 0,
"drawStyle": "line",
"fillOpacity": 10,
"gradientMode": "none",
"hideFrom": { "legend": false, "tooltip": false, "viz": false },
"insertNulls": false,
"lineInterpolation": "smooth",
"lineWidth": 2,
"pointSize": 5,
"scaleDistribution": { "type": "linear" },
"showPoints": "auto",
"spanNulls": false,
"stacking": { "group": "A", "mode": "none" },
"thresholdsStyle": { "mode": "off" }
},
"mappings": [],
"thresholds": {
"mode": "absolute",
"steps": [
{ "color": "green", "value": null },
{ "color": "yellow", "value": 500 },
{ "color": "red", "value": 2000 }
]
},
"unit": "ms"
},
"overrides": []
},
"gridPos": { "h": 10, "w": 16, "x": 0, "y": 116 },
"id": 251,
"options": {
"legend": { "calcs": ["mean", "max"], "displayMode": "table", "placement": "bottom" },
"tooltip": { "mode": "multi", "sort": "desc" }
},
"pluginVersion": "12.3.0",
"targets": [
{
"datasource": { "type": "prometheus", "uid": "PBFA97CFB590B2093" },
"editorMode": "code",
"expr": "histogram_quantile(0.50, sum by (le, http_route) (rate(http_server_duration_milliseconds_bucket{job=\"realestate-crawler-api\"}[5m])))",
"legendFormat": "p50 {{http_route}}",
"range": true,
"refId": "A"
},
{
"datasource": { "type": "prometheus", "uid": "PBFA97CFB590B2093" },
"editorMode": "code",
"expr": "histogram_quantile(0.95, sum by (le, http_route) (rate(http_server_duration_milliseconds_bucket{job=\"realestate-crawler-api\"}[5m])))",
"legendFormat": "p95 {{http_route}}",
"range": true,
"refId": "B"
}
],
"title": "Endpoint Latency p50/p95",
"type": "timeseries"
},
{
"datasource": { "type": "prometheus", "uid": "PBFA97CFB590B2093" },
"description": "p95 latency per endpoint, sorted descending",
"fieldConfig": {
"defaults": {
"mappings": [],
"thresholds": {
"mode": "absolute",
"steps": [
{ "color": "green", "value": null },
{ "color": "yellow", "value": 500 },
{ "color": "red", "value": 2000 }
]
},
"unit": "ms"
},
"overrides": []
},
"gridPos": { "h": 10, "w": 8, "x": 16, "y": 116 },
"id": 252,
"options": {
"displayMode": "gradient",
"maxVizHeight": 300,
"minVizHeight": 16,
"minVizWidth": 8,
"namePlacement": "auto",
"orientation": "horizontal",
"reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false },
"showUnfilled": true,
"sizing": "auto",
"valueMode": "color"
},
"pluginVersion": "12.3.0",
"targets": [
{
"datasource": { "type": "prometheus", "uid": "PBFA97CFB590B2093" },
"editorMode": "code",
"expr": "histogram_quantile(0.95, sum by (le, http_route) (rate(http_server_duration_milliseconds_bucket{job=\"realestate-crawler-api\"}[5m])))",
"legendFormat": "{{http_route}}",
"instant": true,
"refId": "A"
}
],
"title": "Endpoint Latency Ranking (p95)",
"transformations": [
{
"id": "sortBy",
"options": { "fields": {}, "sort": [{ "desc": true, "field": "Value" }] }
}
],
"type": "bargauge"
}
],
"preload": false,