diff --git a/frontend/app/api/cities/detail-batch/route.ts b/frontend/app/api/cities/detail-batch/route.ts index 40436706..a7d8d01d 100644 --- a/frontend/app/api/cities/detail-batch/route.ts +++ b/frontend/app/api/cities/detail-batch/route.ts @@ -1,6 +1,10 @@ import { NextRequest, NextResponse } from "next/server"; import { proxyBackendJsonGet } from "@/lib/api-proxy"; import { buildCityDetailProxyCachePolicy } from "@/lib/proxy-cache-policy"; +import { + createProxyTimer, + finishProxyTimedResponse, +} from "@/lib/proxy-timing"; const API_BASE = process.env.POLYWEATHER_API_BASE_URL; const DETAIL_BATCH_PROXY_TIMEOUT_MS = Number( @@ -8,10 +12,15 @@ const DETAIL_BATCH_PROXY_TIMEOUT_MS = Number( ); export async function GET(req: NextRequest) { + const timer = createProxyTimer(req, "city_detail_batch"); if (!API_BASE) { - return NextResponse.json( - { error: "POLYWEATHER_API_BASE_URL is not configured" }, - { status: 500 }, + return finishProxyTimedResponse( + NextResponse.json( + { error: "POLYWEATHER_API_BASE_URL is not configured" }, + { status: 500 }, + ), + timer, + "missing_api_base", ); } @@ -39,6 +48,7 @@ export async function GET(req: NextRequest) { revalidateSeconds: cachePolicy.revalidateSeconds, signal: controller.signal, timeoutPublicMessage: "City detail batch request timed out", + timing: timer, url: `${API_BASE}/api/cities/detail-batch?${searchParams.toString()}`, }); } finally { diff --git a/frontend/app/api/city/[name]/detail/route.ts b/frontend/app/api/city/[name]/detail/route.ts index 2f8c6afe..b4c9e069 100644 --- a/frontend/app/api/city/[name]/detail/route.ts +++ b/frontend/app/api/city/[name]/detail/route.ts @@ -9,6 +9,10 @@ import { } from "@/lib/api-proxy"; import { buildCachedJsonResponse } from "@/lib/http-cache"; import { buildCityDetailProxyCachePolicy } from "@/lib/proxy-cache-policy"; +import { + createProxyTimer, + finishProxyTimedResponse, +} from "@/lib/proxy-timing"; const API_BASE = process.env.POLYWEATHER_API_BASE_URL; @@ -34,15 +38,16 @@ export async function GET( req: NextRequest, context: { params: Promise<{ name: string }> }, ) { + const timer = createProxyTimer(req, "city_detail"); if (!API_BASE) { const response = NextResponse.json( { error: "POLYWEATHER_API_BASE_URL is not configured" }, { status: 500 }, ); - return response; + return finishProxyTimedResponse(response, timer, "missing_api_base"); } - const { name } = await context.params; + const { name } = await timer.measure("route_params", () => context.params); const forceRefresh = req.nextUrl.searchParams.get("force_refresh") ?? "false"; const cachePolicy = buildCityDetailProxyCachePolicy(forceRefresh, 15); const depth = req.nextUrl.searchParams.get("depth"); @@ -67,31 +72,48 @@ export async function GET( const url = `${API_BASE}/api/city/${encodeURIComponent(name)}/detail?${searchParams.toString()}`; try { - const auth = await buildBackendRequestHeaders(req, { - includeSupabaseIdentity: false, - }); - const res = await fetch(url, { - headers: auth.headers, - ...(cachePolicy.fetchMode === "no-store" - ? { cache: "no-store" as const } - : { next: { revalidate: cachePolicy.revalidateSeconds ?? 15 } }), - }); + const auth = await timer.measure("auth_headers", () => + buildBackendRequestHeaders(req, { + includeSupabaseIdentity: false, + }), + ); + const res = await timer.measure("backend_fetch", () => + fetch(url, { + headers: auth.headers, + ...(cachePolicy.fetchMode === "no-store" + ? { cache: "no-store" as const } + : { next: { revalidate: cachePolicy.revalidateSeconds ?? 15 } }), + }), + ); + const backendServerTiming = res.headers.get("server-timing") || ""; if (!res.ok) { - const raw = await res.text(); + const raw = await timer.measure("backend_read", () => res.text()); const response = buildUpstreamErrorResponse(res.status, raw); - return applyAuthResponseCookies(response, auth.response); + return finishProxyTimedResponse( + applyAuthResponseCookies(response, auth.response), + timer, + `upstream_${res.status}`, + { backendServerTiming }, + ); } - const data = normalizeCityDetailPayload(await res.json()); + const data = normalizeCityDetailPayload( + await timer.measure("backend_read", () => res.json()), + ); const response = buildCachedJsonResponse( req, data, cachePolicy.responseCacheControl, ); - return applyAuthResponseCookies(response, auth.response); + return finishProxyTimedResponse( + applyAuthResponseCookies(response, auth.response), + timer, + "ok", + { backendServerTiming }, + ); } catch (error) { const response = buildProxyExceptionResponse(error, { publicMessage: "Failed to fetch city detail aggregate", }); - return response; + return finishProxyTimedResponse(response, timer, "exception"); } } diff --git a/frontend/app/api/ops/online-users/route.ts b/frontend/app/api/ops/online-users/route.ts index 8902bdc8..fee070f5 100644 --- a/frontend/app/api/ops/online-users/route.ts +++ b/frontend/app/api/ops/online-users/route.ts @@ -5,27 +5,45 @@ import { } from "@/lib/backend-auth"; import { buildProxyExceptionResponse } from "@/lib/api-proxy"; import { requireOpsProxyAuth } from "@/lib/ops-proxy-auth"; +import { + createProxyTimer, + finishProxyTimedResponse, +} from "@/lib/proxy-timing"; const API_BASE = process.env.POLYWEATHER_API_BASE_URL; export async function GET(req: NextRequest) { + const timer = createProxyTimer(req, "ops_online_users"); if (!API_BASE) { - return NextResponse.json( - { error: "POLYWEATHER_API_BASE_URL is not configured" }, - { status: 500 }, + return finishProxyTimedResponse( + NextResponse.json( + { error: "POLYWEATHER_API_BASE_URL is not configured" }, + { status: 500 }, + ), + timer, + "missing_api_base", ); } try { - const auth = await buildBackendRequestHeaders(req); - const authError = requireOpsProxyAuth(req, auth); - if (authError) return authError; + const auth = await timer.measure("auth_headers", () => + buildBackendRequestHeaders(req), + ); + const authError = timer.measureSync("ops_auth", () => + requireOpsProxyAuth(req, auth), + ); + if (authError) { + return finishProxyTimedResponse(authError, timer, "ops_auth_error"); + } - const res = await fetch(`${API_BASE}/api/ops/online-users`, { - headers: auth.headers, - cache: "no-store", - }); - const raw = await res.text(); + const res = await timer.measure("backend_fetch", () => + fetch(`${API_BASE}/api/ops/online-users`, { + headers: auth.headers, + cache: "no-store", + }), + ); + const backendServerTiming = res.headers.get("server-timing") || ""; + const raw = await timer.measure("backend_read", () => res.text()); const response = new NextResponse(raw, { status: res.status, headers: { @@ -33,10 +51,19 @@ export async function GET(req: NextRequest) { "Cache-Control": "no-store", }, }); - return applyAuthResponseCookies(response, auth.response); + return finishProxyTimedResponse( + applyAuthResponseCookies(response, auth.response), + timer, + res.ok ? "ok" : `upstream_${res.status}`, + { backendServerTiming }, + ); } catch (error) { - return buildProxyExceptionResponse(error, { - publicMessage: "Failed to fetch online users", - }); + return finishProxyTimedResponse( + buildProxyExceptionResponse(error, { + publicMessage: "Failed to fetch online users", + }), + timer, + "exception", + ); } } diff --git a/frontend/app/api/scan/terminal/route.ts b/frontend/app/api/scan/terminal/route.ts index 719d10e7..86a5aa01 100644 --- a/frontend/app/api/scan/terminal/route.ts +++ b/frontend/app/api/scan/terminal/route.ts @@ -2,6 +2,10 @@ import { NextRequest, NextResponse } from "next/server"; import { proxyBackendJsonGet } from "@/lib/api-proxy"; import { buildForceRefreshProxyCachePolicy } from "@/lib/proxy-cache-policy"; import { DASHBOARD_REFRESH_POLICY_SEC } from "@/lib/refresh-policy"; +import { + createProxyTimer, + finishProxyTimedResponse, +} from "@/lib/proxy-timing"; const API_BASE = process.env.POLYWEATHER_API_BASE_URL; const SCAN_TERMINAL_PROXY_TIMEOUT_MS = Number( @@ -11,10 +15,15 @@ const SCAN_TERMINAL_PROXY_TIMEOUT_MS = Number( export const maxDuration = 45; export async function GET(req: NextRequest) { + const timer = createProxyTimer(req, "scan_terminal"); if (!API_BASE) { - return NextResponse.json( - { error: "POLYWEATHER_API_BASE_URL is not configured" }, - { status: 500 }, + return finishProxyTimedResponse( + NextResponse.json( + { error: "POLYWEATHER_API_BASE_URL is not configured" }, + { status: 500 }, + ), + timer, + "missing_api_base", ); } @@ -61,6 +70,7 @@ export async function GET(req: NextRequest) { revalidateSeconds: cachePolicy.revalidateSeconds, signal: controller.signal, timeoutPublicMessage: "Scan terminal request timed out", + timing: timer, url, }); } finally { diff --git a/frontend/components/dashboard/scan-terminal/__tests__/refreshCadencePolicy.test.ts b/frontend/components/dashboard/scan-terminal/__tests__/refreshCadencePolicy.test.ts index 86c9f265..d17b05de 100644 --- a/frontend/components/dashboard/scan-terminal/__tests__/refreshCadencePolicy.test.ts +++ b/frontend/components/dashboard/scan-terminal/__tests__/refreshCadencePolicy.test.ts @@ -12,6 +12,7 @@ import { import { MAX_HOURLY_DETAIL_CONCURRENT_REQUESTS, HOURLY_CACHE_TTL_MS, + __resolveCityDetailFromBatchForTest, __readHourlyCacheEntryForTest, __resetHourlyDetailRequestQueueForTest, __runQueuedHourlyDetailRequestForTest, @@ -95,7 +96,7 @@ export async function runTests() { chartLogicSource.includes("primeCityDetailCache"), "visible terminal chart detail fetches should be coalesced into one batch request and prime the shared chart cache", ); - const fetchHourlyBlock = chartLogicSource.match(/async function fetchHourlyForecastForCity[\s\S]*?\n}\n\nfunction fetchCityDetailWithTimeout/)?.[0] || ""; + const fetchHourlyBlock = chartLogicSource.match(/async function fetchHourlyForecastForCity[\s\S]*?\r?\n}\r?\n\r?\nfunction fetchCityDetailWithTimeout/)?.[0] || ""; assert( fetchHourlyBlock.includes("queueCityDetailBatch(city, resParam)") && !fetchHourlyBlock.includes("runQueuedHourlyDetailRequest"), @@ -130,6 +131,19 @@ export async function runTests() { __shouldFetchCityDetailForChartForTest({ city: "paris", documentHidden: true, isChartVisible: true }) === false, "hidden browser tabs should not prefetch city detail", ); + const normalizedBatchDetail = __resolveCityDetailFromBatchForTest( + { + "hong kong": { + city: "hong kong", + timeseries: { hourly: { times: ["00:00"], temps: [32] } }, + }, + } as any, + "Hong Kong", + ) as any; + assert( + normalizedBatchDetail?.city === "hong kong", + "frontend detail batch lookup should accept backend-normalized city keys before falling back to single-city requests", + ); __resetHourlyDetailRequestQueueForTest(); let activeRequests = 0; diff --git a/frontend/components/dashboard/scan-terminal/temperature-chart-logic.ts b/frontend/components/dashboard/scan-terminal/temperature-chart-logic.ts index fecf4f41..39917085 100644 --- a/frontend/components/dashboard/scan-terminal/temperature-chart-logic.ts +++ b/frontend/components/dashboard/scan-terminal/temperature-chart-logic.ts @@ -1073,6 +1073,30 @@ function rejectBatchWaiters( (waiters || []).forEach((waiter) => waiter.reject(reason)); } +function resolveCityDetailFromBatch( + details: Record | undefined, + city: string, +) { + if (!details) return undefined; + const trimmed = String(city || "").trim(); + const direct = + details[city] || + details[trimmed] || + details[trimmed.toLowerCase()] || + details[normalizeCityKey(trimmed)]; + if (direct) return direct; + + const requestedKey = normalizeCityKey(trimmed); + if (!requestedKey) return undefined; + for (const [key, detail] of Object.entries(details)) { + if (!detail) continue; + if (normalizeCityKey(key) === requestedKey) return detail; + const detailCity = (detail as any).city || detail.name || detail.display_name; + if (normalizeCityKey(detailCity) === requestedKey) return detail; + } + return undefined; +} + async function flushCityDetailBatch(resolution: string) { const queue = _cityDetailBatchQueues.get(resolution); if (!queue) return; @@ -1091,7 +1115,7 @@ async function flushCityDetailBatch(resolution: string) { await Promise.all( cities.map(async (city) => { const waiters = queue.waiters.get(city); - const detail = details[city]; + const detail = resolveCityDetailFromBatch(details, city); const data = primeCityDetailCache(city, resolution, detail); if (data) { resolveBatchWaiters(waiters, data); @@ -2426,6 +2450,7 @@ export { HOURLY_CACHE_TTL_MS, _hourlyCache, __readHourlyCacheEntryForTest, + resolveCityDetailFromBatch as __resolveCityDetailFromBatchForTest, __resetHourlyDetailRequestQueueForTest, __runQueuedHourlyDetailRequestForTest, buildChartDomain, diff --git a/frontend/components/ops/__tests__/apiPerformanceTiming.test.ts b/frontend/components/ops/__tests__/apiPerformanceTiming.test.ts new file mode 100644 index 00000000..7ee539f0 --- /dev/null +++ b/frontend/components/ops/__tests__/apiPerformanceTiming.test.ts @@ -0,0 +1,60 @@ +import assert from "node:assert/strict"; +import fs from "node:fs"; +import path from "node:path"; + +function readFrontend(...parts: string[]) { + return fs.readFileSync(path.join(process.cwd(), ...parts), "utf8"); +} + +export function runTests() { + const timingSource = readFrontend("lib", "proxy-timing.ts"); + assert.match( + timingSource, + /createProxyTimer/, + "shared proxy timing helper should create timers for slow API proxies", + ); + assert.match( + timingSource, + /Server-Timing/, + "shared proxy timing helper should write Server-Timing headers for HAR inspection", + ); + assert.doesNotMatch( + timingSource, + /authUserId|authEmail|userId|email/, + "proxy timing logs must avoid raw user ids or emails", + ); + + const apiProxySource = readFrontend("lib", "api-proxy.ts"); + assert.match( + apiProxySource, + /timing\?: ProxyTimer/, + "generic backend JSON proxy should accept an optional timer", + ); + for (const stage of ["auth_headers", "backend_fetch", "backend_read"]) { + assert.match( + apiProxySource, + new RegExp(stage), + `generic backend JSON proxy should measure ${stage}`, + ); + } + + const detailBatchProxy = readFrontend("app", "api", "cities", "detail-batch", "route.ts"); + assert.match(detailBatchProxy, /createProxyTimer\(req,\s*"city_detail_batch"\)/); + assert.match(detailBatchProxy, /timing:\s*timer/); + + const scanTerminalProxy = readFrontend("app", "api", "scan", "terminal", "route.ts"); + assert.match(scanTerminalProxy, /createProxyTimer\(req,\s*"scan_terminal"\)/); + assert.match(scanTerminalProxy, /timing:\s*timer/); + + const cityDetailProxy = readFrontend("app", "api", "city", "[name]", "detail", "route.ts"); + assert.match(cityDetailProxy, /createProxyTimer\(req,\s*"city_detail"\)/); + for (const stage of ["auth_headers", "backend_fetch", "backend_read"]) { + assert.match(cityDetailProxy, new RegExp(stage)); + } + + const onlineUsersProxy = readFrontend("app", "api", "ops", "online-users", "route.ts"); + assert.match(onlineUsersProxy, /createProxyTimer\(req,\s*"ops_online_users"\)/); + for (const stage of ["auth_headers", "ops_auth", "backend_fetch", "backend_read"]) { + assert.match(onlineUsersProxy, new RegExp(stage)); + } +} diff --git a/frontend/lib/api-proxy.ts b/frontend/lib/api-proxy.ts index 1a9e6386..fd3288ce 100644 --- a/frontend/lib/api-proxy.ts +++ b/frontend/lib/api-proxy.ts @@ -5,6 +5,10 @@ import { buildBackendRequestHeaders, } from "@/lib/backend-auth"; import { buildCachedJsonResponse } from "@/lib/http-cache"; +import { + finishProxyTimedResponse, + type ProxyTimer, +} from "@/lib/proxy-timing"; const PASSTHROUGH_UPSTREAM_STATUSES = new Set([ 400, @@ -91,31 +95,59 @@ export async function proxyBackendJsonGet( signal?: AbortSignal; statusOnException?: number; timeoutPublicMessage?: string; + timing?: ProxyTimer; url: string; }, ) { let auth: Awaited> | null = null; + const timing = options.timing; try { - auth = await buildBackendRequestHeaders(req, { - includeSupabaseIdentity: options.includeSupabaseIdentity ?? false, - }); - const res = await fetch(options.url, { - headers: auth.headers, - ...(options.fetchCache - ? { cache: options.fetchCache } - : { next: { revalidate: options.revalidateSeconds ?? 30 } }), - signal: options.signal, - }); + auth = await (timing + ? timing.measure("auth_headers", () => + buildBackendRequestHeaders(req, { + includeSupabaseIdentity: options.includeSupabaseIdentity ?? false, + }), + ) + : buildBackendRequestHeaders(req, { + includeSupabaseIdentity: options.includeSupabaseIdentity ?? false, + })); + const res = await (timing + ? timing.measure("backend_fetch", () => + fetch(options.url, { + headers: auth!.headers, + ...(options.fetchCache + ? { cache: options.fetchCache } + : { next: { revalidate: options.revalidateSeconds ?? 30 } }), + signal: options.signal, + }), + ) + : fetch(options.url, { + headers: auth.headers, + ...(options.fetchCache + ? { cache: options.fetchCache } + : { next: { revalidate: options.revalidateSeconds ?? 30 } }), + signal: options.signal, + })); + const backendServerTiming = res.headers.get("server-timing") || ""; if (!res.ok) { - const raw = await res.text(); + const raw = await (timing + ? timing.measure("backend_read", () => res.text()) + : res.text()); const response = buildUpstreamErrorResponse(res.status, raw, { detailLimit: options.detailLimit, error: options.error, }); - return applyAuthResponseCookies(response, auth.response); + const withCookies = applyAuthResponseCookies(response, auth.response); + return timing + ? finishProxyTimedResponse(withCookies, timing, `upstream_${res.status}`, { + backendServerTiming, + }) + : withCookies; } - const data = await res.json(); + const data = await (timing + ? timing.measure("backend_read", () => res.json()) + : res.json()); const response = options.cacheControl && options.conditionalResponse !== false ? buildCachedJsonResponse(req, data, options.cacheControl) @@ -124,7 +156,12 @@ export async function proxyBackendJsonGet( ? { "Cache-Control": options.cacheControl } : undefined, }); - return applyAuthResponseCookies(response, auth.response); + const withCookies = applyAuthResponseCookies(response, auth.response); + return timing + ? finishProxyTimedResponse(withCookies, timing, "ok", { + backendServerTiming, + }) + : withCookies; } catch (error) { const timedOut = options.signal?.aborted === true; const response = buildProxyExceptionResponse(error, { @@ -134,6 +171,9 @@ export async function proxyBackendJsonGet( : options.publicMessage, status: timedOut ? 504 : options.statusOnException, }); - return auth ? applyAuthResponseCookies(response, auth.response) : response; + const withCookies = auth ? applyAuthResponseCookies(response, auth.response) : response; + return timing + ? finishProxyTimedResponse(withCookies, timing, timedOut ? "timeout" : "exception") + : withCookies; } } diff --git a/frontend/lib/dashboard-types.ts b/frontend/lib/dashboard-types.ts index 9e2da045..add7a983 100644 --- a/frontend/lib/dashboard-types.ts +++ b/frontend/lib/dashboard-types.ts @@ -716,6 +716,7 @@ export interface AiAnalysisStructured { } export interface CityDetail { + city?: string; name: string; display_name: string; detail_depth?: "panel" | "market" | "nearby" | "full"; diff --git a/frontend/lib/proxy-timing.ts b/frontend/lib/proxy-timing.ts new file mode 100644 index 00000000..d0289f2e --- /dev/null +++ b/frontend/lib/proxy-timing.ts @@ -0,0 +1,113 @@ +import type { NextRequest, NextResponse } from "next/server"; + +export type ProxyTimingStage = { + durationMs: number; + name: string; +}; + +export type ProxyTimer = { + hasAuthorization: boolean; + hasSupabaseCookie: boolean; + measure(name: string, action: () => Promise): Promise; + measureSync(name: string, action: () => T): T; + route: string; + stages: ProxyTimingStage[]; + totalMs(): number; +}; + +function proxyNowMs() { + return typeof performance !== "undefined" ? performance.now() : Date.now(); +} + +function hasRequestSupabaseSessionCookie(req: NextRequest) { + return req.cookies.getAll().some((cookie) => { + const name = cookie.name.toLowerCase(); + const value = String(cookie.value || "").trim(); + return Boolean( + value && + (name === "supabase-auth-token" || + (name.startsWith("sb-") && name.includes("-auth-token"))), + ); + }); +} + +export function createProxyTimer(req: NextRequest, route: string): ProxyTimer { + const startedAt = proxyNowMs(); + const stages: ProxyTimingStage[] = []; + const recordStage = (name: string, stageStartedAt: number) => { + stages.push({ + durationMs: Math.round((proxyNowMs() - stageStartedAt) * 10) / 10, + name, + }); + }; + + return { + hasAuthorization: Boolean(req.headers.get("authorization")), + hasSupabaseCookie: hasRequestSupabaseSessionCookie(req), + async measure(name: string, action: () => Promise) { + const stageStartedAt = proxyNowMs(); + try { + return await action(); + } finally { + recordStage(name, stageStartedAt); + } + }, + measureSync(name: string, action: () => T) { + const stageStartedAt = proxyNowMs(); + try { + return action(); + } finally { + recordStage(name, stageStartedAt); + } + }, + route, + stages, + totalMs() { + return Math.round((proxyNowMs() - startedAt) * 10) / 10; + }, + }; +} + +function formatServerTiming(stages: ProxyTimingStage[]) { + return stages + .map(({ durationMs, name }) => { + const safeName = name.replace(/[^A-Za-z0-9_-]/g, "_"); + return `${safeName};dur=${Math.max(0, durationMs).toFixed(1)}`; + }) + .join(", "); +} + +export function finishProxyTimedResponse( + response: NextResponse, + timer: ProxyTimer, + outcome: string, + extra?: { backendServerTiming?: string }, +) { + const total = timer.totalMs(); + const ownServerTiming = formatServerTiming( + [...timer.stages, { durationMs: total, name: "total" }].map((stage) => ({ + ...stage, + name: `${timer.route}_${stage.name}`, + })), + ); + const backendServerTiming = String(extra?.backendServerTiming || "").trim(); + response.headers.set( + "Server-Timing", + backendServerTiming + ? `${ownServerTiming}, ${backendServerTiming}` + : ownServerTiming, + ); + console.info( + "[api-proxy-timing]", + JSON.stringify({ + hasAuthorization: timer.hasAuthorization, + hasSupabaseCookie: timer.hasSupabaseCookie, + outcome, + route: timer.route, + stages: timer.stages, + status: response.status, + totalMs: total, + }), + ); + return response; +} diff --git a/tests/test_api_performance_timing.py b/tests/test_api_performance_timing.py new file mode 100644 index 00000000..d5ef660f --- /dev/null +++ b/tests/test_api_performance_timing.py @@ -0,0 +1,116 @@ +from pathlib import Path + +from fastapi.testclient import TestClient + +from web.app import app +import web.services.city_api as city_api +import web.services.scan_api as scan_api + + +ROOT = Path(__file__).resolve().parents[1] +client = TestClient(app) + + +def test_backend_shared_timing_helper_avoids_sensitive_identity_fields(): + source = (ROOT / "web" / "services" / "request_timing.py").read_text( + encoding="utf-8" + ) + + assert "ServerTimingRecorder" in source + assert "server_timing_value" in source + assert "user_id" not in source + assert "email" not in source + + +def test_city_detail_batch_response_includes_backend_server_timing(monkeypatch): + class FakeCache: + def get_city_cache(self, kind, city): + assert kind == "full" + return {"payload": {"city": city, "hourly": {"times": [], "temps": []}}} + + def build_detail(data, market_slug, target_date, resolution): + return {"city": data["city"], "resolution": resolution} + + monkeypatch.setattr(city_api.legacy_routes, "_assert_entitlement", lambda request: None) + monkeypatch.setattr( + city_api.legacy_routes, + "_normalize_city_or_404", + lambda name: name.strip().lower(), + ) + monkeypatch.setattr(city_api.legacy_routes, "_city_cache_is_fresh", lambda entry, ttl: True) + monkeypatch.setattr( + city_api.legacy_routes, + "_overlay_latest_wunderground_current", + lambda city, payload: payload, + ) + monkeypatch.setattr(city_api.legacy_routes, "_CACHE_DB", FakeCache()) + monkeypatch.setattr(city_api.legacy_routes, "_build_city_detail_payload", build_detail) + + response = client.get("/api/cities/detail-batch?cities=Paris&resolution=10m") + + assert response.status_code == 200 + server_timing = response.headers["server-timing"] + assert "city_detail_batch_assert_entitlement" in server_timing + assert "city_detail_batch_full_data_paris" in server_timing + assert "city_detail_batch_detail_payload_paris" in server_timing + assert "city_detail_batch_total" in server_timing + + +def test_city_detail_response_includes_backend_server_timing(monkeypatch): + class FakeCache: + def get_city_cache(self, kind, city): + assert kind == "full" + return {"payload": {"city": city, "hourly": {"times": [], "temps": []}}} + + def build_detail(data, market_slug, target_date, resolution): + return {"city": data["city"], "resolution": resolution} + + monkeypatch.setattr(city_api.legacy_routes, "_assert_entitlement", lambda request: None) + monkeypatch.setattr( + city_api.legacy_routes, + "_normalize_city_or_404", + lambda name: name.strip().lower(), + ) + monkeypatch.setattr(city_api.legacy_routes, "_city_cache_is_fresh", lambda entry, ttl: True) + monkeypatch.setattr( + city_api.legacy_routes, + "_overlay_latest_wunderground_current", + lambda city, payload: payload, + ) + monkeypatch.setattr(city_api.legacy_routes, "_CACHE_DB", FakeCache()) + monkeypatch.setattr(city_api.legacy_routes, "_build_city_detail_payload", build_detail) + + response = client.get("/api/city/Paris/detail?resolution=10m") + + assert response.status_code == 200 + server_timing = response.headers["server-timing"] + assert "city_detail_assert_entitlement" in server_timing + assert "city_detail_full_data" in server_timing + assert "city_detail_detail_payload" in server_timing + assert "city_detail_total" in server_timing + + +def test_scan_terminal_response_includes_backend_server_timing(monkeypatch): + monkeypatch.setattr(scan_api.legacy_routes, "_assert_entitlement", lambda request: None) + monkeypatch.setattr( + scan_api.legacy_routes, + "build_scan_terminal_payload", + lambda filters, force_refresh=False, timing_recorder=None: {"rows": [], "filters": filters}, + ) + + response = client.get("/api/scan/terminal?limit=1") + + assert response.status_code == 200 + server_timing = response.headers["server-timing"] + assert "scan_terminal_assert_entitlement" in server_timing + assert "scan_terminal_build_payload" in server_timing + assert "scan_terminal_total" in server_timing + + +def test_online_users_response_includes_backend_server_timing(): + response = client.get("/api/ops/online-users") + + assert response.status_code == 200 + server_timing = response.headers["server-timing"] + assert "ops_online_users_online_count" in server_timing + assert "ops_online_users_total" in server_timing diff --git a/web/routers/city.py b/web/routers/city.py index 64682acb..c3b11693 100644 --- a/web/routers/city.py +++ b/web/routers/city.py @@ -2,7 +2,7 @@ from typing import Any, Dict, List, Optional -from fastapi import APIRouter, BackgroundTasks, Query, Request +from fastapi import APIRouter, BackgroundTasks, Query, Request, Response from web.services.city_api import ( get_city_detail_batch_payload, @@ -12,6 +12,7 @@ from web.services.city_api import ( list_cities_payload, ) from web.services.city_realtime_stream import get_realtime_stream_payload +from web.services.request_timing import attach_server_timing_header router = APIRouter(tags=["city"]) @@ -108,6 +109,7 @@ async def cities_model_range( @router.get("/api/cities/detail-batch") async def city_detail_batch( request: Request, + response: Response, cities: str = "", force_refresh: bool = False, market_slug: Optional[str] = None, @@ -115,7 +117,7 @@ async def city_detail_batch( resolution: Optional[str] = "10m", limit: int = 12, ): - return await get_city_detail_batch_payload( + payload = await get_city_detail_batch_payload( request, cities=cities, force_refresh=force_refresh, @@ -124,6 +126,8 @@ async def city_detail_batch( resolution=resolution, limit=limit, ) + attach_server_timing_header(response, request, "city_detail_batch_server_timing") + return payload @router.get("/api/city/{name}") @@ -159,13 +163,14 @@ async def city_summary( @router.get("/api/city/{name}/detail") async def city_detail_aggregate( request: Request, + response: Response, name: str, force_refresh: bool = False, market_slug: Optional[str] = None, target_date: Optional[str] = None, resolution: Optional[str] = "10m", ): - return await get_city_detail_aggregate_payload( + payload = await get_city_detail_aggregate_payload( request, name, force_refresh=force_refresh, @@ -173,6 +178,8 @@ async def city_detail_aggregate( target_date=target_date, resolution=resolution, ) + attach_server_timing_header(response, request, "city_detail_server_timing") + return payload @router.get("/api/city/{name}/realtime-stream") diff --git a/web/routers/ops.py b/web/routers/ops.py index e0711da8..4e7b0cf7 100644 --- a/web/routers/ops.py +++ b/web/routers/ops.py @@ -1,6 +1,6 @@ """Operations/admin API routes.""" -from fastapi import APIRouter, Request +from fastapi import APIRouter, Request, Response from web.core import GrantPointsRequest from web.services.ops_api import ( @@ -30,14 +30,35 @@ from web.services.ops_api import ( get_ops_training_accuracy, get_ops_telegram_audit, ) +from web.services.request_timing import ServerTimingRecorder, attach_server_timing_header router = APIRouter(tags=["ops"]) @router.get("/api/ops/online-users") -async def ops_online_users(): - from src.utils.online_tracker import online_count - return {"online": online_count()} +async def ops_online_users(request: Request, response: Response): + timer = ServerTimingRecorder( + request, + log_name="ops_online_users_timing", + prefix="ops_online_users", + state_attr="ops_online_users_server_timing", + ) + outcome = "ok" + status_code = 200 + try: + from src.utils.online_tracker import online_count + return {"online": timer.measure("online_count", online_count)} + except Exception: + outcome = "exception" + status_code = 500 + raise + finally: + timer.finish(outcome=outcome, status_code=status_code) + attach_server_timing_header( + response, + request, + "ops_online_users_server_timing", + ) @router.get("/api/ops/users") diff --git a/web/routers/scan.py b/web/routers/scan.py index a9ea7ff5..fce64368 100644 --- a/web/routers/scan.py +++ b/web/routers/scan.py @@ -9,6 +9,7 @@ from web.services.scan_api import ( get_scan_terminal_overview_payload, get_scan_terminal_payload, ) +from web.services.request_timing import attach_server_timing_header router = APIRouter(tags=["scan"]) @@ -45,12 +46,14 @@ async def scan_terminal( region=region or trading_region or None, timezone_offset_seconds=timezone_offset_seconds, ) - return JSONResponse( + response = JSONResponse( content=payload, headers={ "Cache-Control": "public, s-maxage=30, stale-while-revalidate=120", }, ) + attach_server_timing_header(response, request, "scan_terminal_server_timing") + return response @router.post("/api/scan/terminal/overview") diff --git a/web/scan_terminal_service.py b/web/scan_terminal_service.py index de8361e7..9e229888 100644 --- a/web/scan_terminal_service.py +++ b/web/scan_terminal_service.py @@ -235,16 +235,41 @@ def build_scan_terminal_payload( raw_filters: Optional[Dict[str, Any]] = None, *, force_refresh: bool = False, + timing_recorder: Any = None, ) -> Dict[str, Any]: - filters = _normalize_scan_terminal_filters(raw_filters) + filters = ( + timing_recorder.measure( + "normalize_filters", + lambda: _normalize_scan_terminal_filters(raw_filters), + ) + if timing_recorder is not None + else _normalize_scan_terminal_filters(raw_filters) + ) if not force_refresh: - cached = get_cached_scan_terminal_payload( - filters, ttl_sec=SCAN_TERMINAL_PAYLOAD_TTL_SEC + cached = ( + timing_recorder.measure( + "cache_lookup", + lambda: get_cached_scan_terminal_payload( + filters, + ttl_sec=SCAN_TERMINAL_PAYLOAD_TTL_SEC, + ), + ) + if timing_recorder is not None + else get_cached_scan_terminal_payload( + filters, ttl_sec=SCAN_TERMINAL_PAYLOAD_TTL_SEC + ) ) if cached is not None: return cached - cached_entry = get_scan_terminal_cache_entry(filters) or {} + cached_entry = ( + timing_recorder.measure( + "stale_cache_lookup", + lambda: get_scan_terminal_cache_entry(filters) or {}, + ) + if timing_recorder is not None + else get_scan_terminal_cache_entry(filters) or {} + ) success_payload = cached_entry.get("success_payload") if isinstance(success_payload, dict) and success_payload: started = _start_scan_terminal_background_refresh(filters) @@ -257,7 +282,17 @@ def build_scan_terminal_payload( failed_at=cached_entry.get("last_failed_at"), ) - return _build_scan_terminal_payload_uncached(filters, force_refresh=force_refresh) + return ( + timing_recorder.measure( + "uncached_build", + lambda: _build_scan_terminal_payload_uncached( + filters, + force_refresh=force_refresh, + ), + ) + if timing_recorder is not None + else _build_scan_terminal_payload_uncached(filters, force_refresh=force_refresh) + ) _SCAN_PREWARM_STARTED = False diff --git a/web/services/city_api.py b/web/services/city_api.py index 36db7e09..ec165e1a 100644 --- a/web/services/city_api.py +++ b/web/services/city_api.py @@ -13,6 +13,7 @@ from fastapi.concurrency import run_in_threadpool from loguru import logger import web.routes as legacy_routes +from web.services.request_timing import ServerTimingRecorder _RECENT_DEB_CACHE: Optional[Dict[str, Dict[str, object]]] = None _RECENT_DEB_CACHE_TS = 0.0 @@ -368,16 +369,41 @@ async def get_city_detail_aggregate_payload( target_date: Optional[str] = None, resolution: Optional[str] = "10m", ) -> Dict[str, Any]: - legacy_routes._assert_entitlement(request) - city = legacy_routes._normalize_city_or_404(name) - data = await _get_city_full_data(city, force_refresh=force_refresh) - - return await _build_city_detail_payload_cached( - data, - market_slug, - target_date, - resolution, + timer = ServerTimingRecorder( + request, + log_name="city_detail_timing", + prefix="city_detail", + state_attr="city_detail_server_timing", ) + outcome = "ok" + status_code = 200 + try: + timer.measure("assert_entitlement", lambda: legacy_routes._assert_entitlement(request)) + city = timer.measure("normalize_city", lambda: legacy_routes._normalize_city_or_404(name)) + data = await timer.measure_async( + "full_data", + lambda: _get_city_full_data(city, force_refresh=force_refresh), + ) + + return await timer.measure_async( + "detail_payload", + lambda: _build_city_detail_payload_cached( + data, + market_slug, + target_date, + resolution, + ), + ) + except HTTPException as exc: + outcome = f"http_{exc.status_code}" + status_code = exc.status_code + raise + except Exception: + outcome = "exception" + status_code = 500 + raise + finally: + timer.finish(outcome=outcome, status_code=status_code) def _parse_batch_city_names(raw_cities: str, *, limit: int) -> List[str]: @@ -404,14 +430,30 @@ async def _build_city_detail_batch_item_async( market_slug: Optional[str], target_date: Optional[str], resolution: Optional[str], + timing_recorder: Optional[ServerTimingRecorder] = None, ) -> Tuple[str, Dict[str, Any]]: - data = await _get_city_full_data(city, force_refresh=force_refresh) - detail = await _build_city_detail_payload_cached( - data, - market_slug, - target_date, - resolution, - ) + if timing_recorder is not None: + data = await timing_recorder.measure_async( + f"full_data_{city}", + lambda: _get_city_full_data(city, force_refresh=force_refresh), + ) + detail = await timing_recorder.measure_async( + f"detail_payload_{city}", + lambda: _build_city_detail_payload_cached( + data, + market_slug, + target_date, + resolution, + ), + ) + else: + data = await _get_city_full_data(city, force_refresh=force_refresh) + detail = await _build_city_detail_payload_cached( + data, + market_slug, + target_date, + resolution, + ) return city, detail @@ -433,39 +475,68 @@ async def get_city_detail_batch_payload( resolution: Optional[str] = "10m", limit: int = 12, ) -> Dict[str, Any]: - legacy_routes._assert_entitlement(request) - city_names = _parse_batch_city_names(cities, limit=max(1, min(24, int(limit or 12)))) - if not city_names: - return {"cities": [], "details": {}, "errors": {}} + timer = ServerTimingRecorder( + request, + log_name="city_detail_batch_timing", + prefix="city_detail_batch", + state_attr="city_detail_batch_server_timing", + ) + outcome = "ok" + status_code = 200 + try: + timer.measure("assert_entitlement", lambda: legacy_routes._assert_entitlement(request)) + city_names = timer.measure( + "parse_cities", + lambda: _parse_batch_city_names( + cities, + limit=max(1, min(24, int(limit or 12))), + ), + ) + if not city_names: + return {"cities": [], "details": {}, "errors": {}} - semaphore = asyncio.Semaphore(_city_detail_batch_concurrency()) + semaphore = asyncio.Semaphore(_city_detail_batch_concurrency()) - async def _build_with_limit(city: str) -> Tuple[str, Dict[str, Any]]: - async with semaphore: - return await _build_city_detail_batch_item_async( - city, - force_refresh=force_refresh, - market_slug=market_slug, - target_date=target_date, - resolution=resolution, - ) + async def _build_with_limit(city: str) -> Tuple[str, Dict[str, Any]]: + async with semaphore: + return await _build_city_detail_batch_item_async( + city, + force_refresh=force_refresh, + market_slug=market_slug, + target_date=target_date, + resolution=resolution, + timing_recorder=timer, + ) - tasks = [ - _build_with_limit(city) - for city in city_names - ] - results = await asyncio.gather(*tasks, return_exceptions=True) - details: Dict[str, Any] = {} - errors: Dict[str, str] = {} - for city, result in zip(city_names, results): - if isinstance(result, Exception): - errors[city] = str(result) - continue - result_city, payload = result - details[result_city] = payload + tasks = [ + _build_with_limit(city) + for city in city_names + ] + results = await timer.measure_async( + "build_details", + lambda: asyncio.gather(*tasks, return_exceptions=True), + ) + details: Dict[str, Any] = {} + errors: Dict[str, str] = {} + for city, result in zip(city_names, results): + if isinstance(result, Exception): + errors[city] = str(result) + continue + result_city, payload = result + details[result_city] = payload - return { - "cities": city_names, - "details": details, - "errors": errors, - } + return { + "cities": city_names, + "details": details, + "errors": errors, + } + except HTTPException as exc: + outcome = f"http_{exc.status_code}" + status_code = exc.status_code + raise + except Exception: + outcome = "exception" + status_code = 500 + raise + finally: + timer.finish(outcome=outcome, status_code=status_code) diff --git a/web/services/request_timing.py b/web/services/request_timing.py new file mode 100644 index 00000000..9a705197 --- /dev/null +++ b/web/services/request_timing.py @@ -0,0 +1,87 @@ +"""Small helpers for exposing request stage timings via Server-Timing.""" + +from __future__ import annotations + +import re +import threading +import time +from typing import Awaitable, Callable, Dict, Optional, TypeVar + +from fastapi import Request, Response +from loguru import logger + + +T = TypeVar("T") + + +class ServerTimingRecorder: + def __init__( + self, + request: Optional[Request], + *, + log_name: str, + prefix: str, + state_attr: str, + ) -> None: + self.request = request + self.log_name = log_name + self.prefix = prefix + self.state_attr = state_attr + self.started = time.perf_counter() + self.timings_ms: Dict[str, float] = {} + self._lock = threading.Lock() + + def _record(self, stage: str, started: float) -> None: + elapsed_ms = round((time.perf_counter() - started) * 1000.0, 1) + with self._lock: + self.timings_ms[stage] = elapsed_ms + + def measure(self, stage: str, action: Callable[[], T]) -> T: + started = time.perf_counter() + try: + return action() + finally: + self._record(stage, started) + + async def measure_async(self, stage: str, action: Callable[[], Awaitable[T]]) -> T: + started = time.perf_counter() + try: + return await action() + finally: + self._record(stage, started) + + def server_timing_value(self) -> str: + with self._lock: + items = list(self.timings_ms.items()) + return ", ".join( + f"{self._metric_name(stage)};dur={max(0.0, duration):.1f}" + for stage, duration in items + ) + + def finish(self, *, outcome: str, status_code: int) -> None: + self._record("total", self.started) + value = self.server_timing_value() + state = getattr(self.request, "state", None) + if state is not None: + setattr(state, self.state_attr, value) + logger.info( + "{} outcome={} status_code={} timings_ms={}", + self.log_name, + outcome, + status_code, + dict(self.timings_ms), + ) + + def _metric_name(self, stage: str) -> str: + raw = f"{self.prefix}_{stage}" + return re.sub(r"[^A-Za-z0-9_-]", "_", raw) + + +def attach_server_timing_header( + response: Response, + request: Request, + state_attr: str, +) -> None: + value = str(getattr(request.state, state_attr, "") or "").strip() + if value: + response.headers["Server-Timing"] = value diff --git a/web/services/scan_api.py b/web/services/scan_api.py index 446be67f..e131e8da 100644 --- a/web/services/scan_api.py +++ b/web/services/scan_api.py @@ -2,12 +2,25 @@ from __future__ import annotations +from inspect import Parameter, signature from typing import Any, Dict -from fastapi import Request +from fastapi import HTTPException, Request from fastapi.concurrency import run_in_threadpool import web.routes as legacy_routes +from web.services.request_timing import ServerTimingRecorder + + +def _supports_timing_recorder(func: Any) -> bool: + try: + params = signature(func).parameters.values() + except (TypeError, ValueError): + return True + return any( + param.name == "timing_recorder" or param.kind == Parameter.VAR_KEYWORD + for param in params + ) async def get_scan_terminal_payload( @@ -26,27 +39,49 @@ async def get_scan_terminal_payload( region: str = "", timezone_offset_seconds: int | None = None, ) -> Dict[str, Any]: - legacy_routes._assert_entitlement(request) - filters: Dict[str, Any] = { - "scan_mode": scan_mode, - "min_price": min_price, - "max_price": max_price, - "min_edge_pct": min_edge_pct, - "min_liquidity": min_liquidity, - "high_liquidity_only": high_liquidity_only, - "market_type": market_type, - "time_range": time_range, - "limit": limit, - } - if timezone_offset_seconds is not None: - filters["timezone_offset_seconds"] = timezone_offset_seconds - if region: - filters["trading_region"] = region - return await run_in_threadpool( - legacy_routes.build_scan_terminal_payload, - filters, - force_refresh=force_refresh, + timer = ServerTimingRecorder( + request, + log_name="scan_terminal_timing", + prefix="scan_terminal", + state_attr="scan_terminal_server_timing", ) + outcome = "ok" + status_code = 200 + try: + timer.measure("assert_entitlement", lambda: legacy_routes._assert_entitlement(request)) + filters: Dict[str, Any] = { + "scan_mode": scan_mode, + "min_price": min_price, + "max_price": max_price, + "min_edge_pct": min_edge_pct, + "min_liquidity": min_liquidity, + "high_liquidity_only": high_liquidity_only, + "market_type": market_type, + "time_range": time_range, + "limit": limit, + } + if timezone_offset_seconds is not None: + filters["timezone_offset_seconds"] = timezone_offset_seconds + if region: + filters["trading_region"] = region + async def build_payload(): + builder = legacy_routes.build_scan_terminal_payload + kwargs: Dict[str, Any] = {"force_refresh": force_refresh} + if _supports_timing_recorder(builder): + kwargs["timing_recorder"] = timer + return await run_in_threadpool(builder, filters, **kwargs) + + return await timer.measure_async("build_payload", build_payload) + except HTTPException as exc: + outcome = f"http_{exc.status_code}" + status_code = exc.status_code + raise + except Exception: + outcome = "exception" + status_code = 500 + raise + finally: + timer.finish(outcome=outcome, status_code=status_code) async def get_scan_terminal_overview_payload(request: Request) -> Dict[str, Any]: