From b2e15bbd2a1ced1400d03e9105889e581e02d3e6 Mon Sep 17 00:00:00 2001 From: Jakob Wennberg Date: Wed, 26 Aug 2026 13:55:42 +0200 Subject: [PATCH] feat(perf): measure the auth proxy per request (Server-Timing + proxy completed log) (#1922) The proxy in front of every page, RSC, prefetch and /api request makes several sequential network calls (getUser, session state, the resolve_active_company RPC, MFA factor lookups) and nothing measured them, while the route wrapper has logged authMs/companyMs/handlerMs per API call for months. This is the first PR of the responsiveness plan (customer report: "it takes time before all fields load when clicking around"): the baseline every later change is measured against. - lib/supabase/proxy-timing.ts: pure helpers (request classification from the app-router headers, route template that collapses ids and tokens, Server-Timing formatting, a timed() accumulator). - lib/supabase/middleware.ts: updateSession wraps updateSessionInner, times each phase, sets Server-Timing on page/RSC/prefetch responses and X-Proxy-Timing on /api responses (withRouteContext owns Server-Timing there), and emits one "proxy completed" log line per request. - scripts/perf/log-percentiles.ts: p50/p90/p99 per group over `vercel logs --json` output, for both "op completed" and "proxy completed"; scripts/perf/README.md documents the protocol and targets. Co-authored-by: Jakob Wennberg <311770904+jakobwennberg-oss@users.noreply.github.com> Co-authored-by: Claude Fable 5 --- lib/supabase/__tests__/middleware.test.ts | 75 +++++++ lib/supabase/__tests__/proxy-timing.test.ts | 83 ++++++++ lib/supabase/middleware.ts | 77 +++++++- lib/supabase/proxy-timing.ts | 115 +++++++++++ scripts/__tests__/log-percentiles.test.ts | 123 ++++++++++++ scripts/perf/README.md | 69 +++++++ scripts/perf/log-percentiles.ts | 205 ++++++++++++++++++++ 7 files changed, 738 insertions(+), 9 deletions(-) create mode 100644 lib/supabase/__tests__/proxy-timing.test.ts create mode 100644 lib/supabase/proxy-timing.ts create mode 100644 scripts/__tests__/log-percentiles.test.ts create mode 100644 scripts/perf/README.md create mode 100644 scripts/perf/log-percentiles.ts diff --git a/lib/supabase/__tests__/middleware.test.ts b/lib/supabase/__tests__/middleware.test.ts index 045c02b5..aac4a9f8 100644 --- a/lib/supabase/__tests__/middleware.test.ts +++ b/lib/supabase/__tests__/middleware.test.ts @@ -72,6 +72,19 @@ vi.mock('@supabase/ssr', () => ({ })), })) +const logState = vi.hoisted(() => ({ info: vi.fn() })) + +vi.mock('@/lib/logger', () => { + const logger = { + info: (...args: unknown[]) => logState.info(...args), + warn: vi.fn(), + error: vi.fn(), + debug: vi.fn(), + child: () => logger, + } + return { createLogger: () => logger } +}) + import { updateSession } from '../middleware' import { createSessionTimeoutState, @@ -103,6 +116,7 @@ describe('updateSession redirect destinations', () => { beforeEach(() => { vi.clearAllMocks() + logState.info.mockClear() state.user = null state.sessionId = 'session-1' state.authError = null @@ -535,6 +549,67 @@ describe('updateSession redirect destinations', () => { // ── MFA semantics that must not change ──────────────────────────────── + describe('per-request timing header and log line', () => { + const TIMING_RE = + /^mw-auth;dur=\d+, mw-session;dur=\d+, mw-company;dur=\d+, mw-mfa;dur=\d+, mw-total;dur=\d+$/ + + function lastLog() { + expect(logState.info).toHaveBeenCalledTimes(1) + const [msg, ctx] = logState.info.mock.calls[0] as [string, Record] + expect(msg).toBe('proxy completed') + return ctx + } + + it('page responses carry Server-Timing and log kind=page with the route', async () => { + state.user = SIGNED_IN + const res = await run('/invoices') + expect(res.status).toBe(200) + expect(res.headers.get('server-timing')).toMatch(TIMING_RE) + expect(res.headers.get('x-proxy-timing')).toBeNull() + const ctx = lastLog() + expect(ctx.kind).toBe('page') + expect(ctx.route).toBe('/invoices') + expect(ctx.status).toBe(200) + expect(typeof ctx.totalMs).toBe('number') + expect(typeof ctx.authMs).toBe('number') + expect(typeof ctx.companyMs).toBe('number') + }) + + it('classifies prefetch and RSC requests from the app-router headers', async () => { + state.user = SIGNED_IN + await run('/invoices', { headers: { 'next-router-prefetch': '1', rsc: '1' } }) + expect(lastLog().kind).toBe('prefetch') + logState.info.mockClear() + await run('/invoices', { headers: { rsc: '1' } }) + expect(lastLog().kind).toBe('rsc') + }) + + it('/api responses use X-Proxy-Timing and leave Server-Timing to the route wrapper', async () => { + state.user = SIGNED_IN + const res = await run('/api/settings') + expect(res.headers.get('x-proxy-timing')).toMatch(TIMING_RE) + expect(res.headers.get('server-timing')).toBeNull() + expect(lastLog().kind).toBe('api') + }) + + it('redirect responses also carry the header and log their status', async () => { + const res = await run('/invoices') + expect(res.status).toBe(307) + expect(res.headers.get('server-timing')).toMatch(TIMING_RE) + expect(lastLog().status).toBe(307) + }) + + it('never logs a token-carrying path or a raw entity id', async () => { + const res = await run('/invite/9f8e7d6c5b4a3928171605f4e3d2c1b0') + expect(res.status).toBe(200) + expect(lastLog().route).toBe('/invite/*') + logState.info.mockClear() + state.user = SIGNED_IN + await run('/invoices/6f1c2a3e-1234-4bcd-9abc-0123456789ab') + expect(lastLog().route).toBe('/invoices/:id') + }) + }) + describe('MFA-disabled and self-hosted paths are unchanged', () => { it('does not redirect when NEXT_PUBLIC_REQUIRE_MFA is unset', async () => { state.user = SIGNED_IN diff --git a/lib/supabase/__tests__/proxy-timing.test.ts b/lib/supabase/__tests__/proxy-timing.test.ts new file mode 100644 index 00000000..3cc36b79 --- /dev/null +++ b/lib/supabase/__tests__/proxy-timing.test.ts @@ -0,0 +1,83 @@ +import { describe, it, expect } from 'vitest' +import { + classifyProxyRequest, + createProxyTimings, + formatProxyServerTiming, + proxyRouteTemplate, + timed, +} from '../proxy-timing' + +describe('classifyProxyRequest', () => { + it('treats /api paths as api regardless of headers', () => { + const headers = new Headers({ 'next-router-prefetch': '1', rsc: '1' }) + expect(classifyProxyRequest('/api/settings', headers)).toBe('api') + }) + + it('recognises app-router prefetch and RSC requests by header', () => { + expect( + classifyProxyRequest('/invoices', new Headers({ 'Next-Router-Prefetch': '1', RSC: '1' })), + ).toBe('prefetch') + expect(classifyProxyRequest('/invoices', new Headers({ RSC: '1' }))).toBe('rsc') + }) + + it('falls back to page for a plain document request', () => { + expect(classifyProxyRequest('/invoices', new Headers())).toBe('page') + }) +}) + +describe('proxyRouteTemplate', () => { + it('replaces UUID and numeric segments with placeholders', () => { + expect(proxyRouteTemplate('/invoices/6f1c2a3e-1234-4bcd-9abc-0123456789ab/edit')).toBe( + '/invoices/:id/edit', + ) + expect(proxyRouteTemplate('/salary/runs/42')).toBe('/salary/runs/:n') + }) + + it('collapses token-carrying prefixes so secrets never reach the log', () => { + expect(proxyRouteTemplate('/invite/9f8e7d6c5b4a3928171605f4e3d2c1b0')).toBe('/invite/*') + expect(proxyRouteTemplate('/payslip/abc')).toBe('/payslip/*') + expect(proxyRouteTemplate('/auth/callback')).toBe('/auth/*') + expect(proxyRouteTemplate('/auth')).toBe('/auth/*') + }) + + it('masks long opaque segments outside the known prefixes', () => { + expect(proxyRouteTemplate('/e/sector/aVeryLongOpaqueSlugThatLooksLikeAToken')).toBe( + '/e/sector/:token', + ) + }) + + it('keeps ordinary routes and the root untouched', () => { + expect(proxyRouteTemplate('/settings/company')).toBe('/settings/company') + expect(proxyRouteTemplate('/')).toBe('/') + }) +}) + +describe('formatProxyServerTiming', () => { + it('emits one mw-* metric per phase plus the total', () => { + const timing = { authMs: 12, sessionMs: 3, companyMs: 40, mfaMs: 0 } + expect(formatProxyServerTiming(timing, 61)).toBe( + 'mw-auth;dur=12, mw-session;dur=3, mw-company;dur=40, mw-mfa;dur=0, mw-total;dur=61', + ) + }) +}) + +describe('timed', () => { + it('returns the wrapped value and accumulates elapsed time on the key', async () => { + const timing = createProxyTimings() + const value = await timed(timing, 'sessionMs', async () => 'ok') + expect(value).toBe('ok') + await timed(timing, 'sessionMs', async () => undefined) + expect(timing.sessionMs).toBeGreaterThanOrEqual(0) + expect(timing.authMs).toBe(0) + }) + + it('still records time when the wrapped call throws', async () => { + const timing = createProxyTimings() + await expect( + timed(timing, 'authMs', async () => { + throw new Error('boom') + }), + ).rejects.toThrow('boom') + expect(timing.authMs).toBeGreaterThanOrEqual(0) + }) +}) diff --git a/lib/supabase/middleware.ts b/lib/supabase/middleware.ts index 487703bd..146912dd 100644 --- a/lib/supabase/middleware.ts +++ b/lib/supabase/middleware.ts @@ -1,5 +1,15 @@ import { createServerClient } from '@supabase/ssr' import { NextResponse, type NextRequest } from 'next/server' +import { createLogger } from '@/lib/logger' +import { + PROXY_TIMING_HEADER, + classifyProxyRequest, + createProxyTimings, + formatProxyServerTiming, + proxyRouteTemplate, + timed, + type ProxyTimings, +} from '@/lib/supabase/proxy-timing' import { shouldEnforceMfa } from '@/lib/auth/mfa' import { apiPathSkipsMfaGate } from '@/lib/auth/api-mfa-gate' import { DEFAULT_LOCALE, LOCALE_COOKIE, isLocale } from '@/i18n/config' @@ -27,7 +37,43 @@ import { type SessionTimeoutReason, } from '@/lib/auth/session-timeout-shared' +const log = createLogger('proxy') + +/** + * Auth proxy entry point. Wraps the real work so every response carries a + * per-phase timing header and emits one structured log line, mirroring what + * withRouteContext does for API routes: without it the proxy's sequential + * network calls (getUser, session state, company RPC, MFA lookups) were the + * one part of a request nobody could measure. Page/RSC/prefetch responses + * get `Server-Timing` (visible in the browser Timing tab); /api responses + * get `X-Proxy-Timing` so the route wrapper's own Server-Timing is left + * alone. Token-carrying paths are collapsed before logging. + */ export async function updateSession(request: NextRequest) { + const start = Date.now() + const timing = createProxyTimings() + const response = await updateSessionInner(request, timing) + const totalMs = Date.now() - start + const pathname = request.nextUrl.pathname + const kind = classifyProxyRequest(pathname, request.headers) + response.headers.set( + kind === 'api' ? PROXY_TIMING_HEADER : 'Server-Timing', + formatProxyServerTiming(timing, totalMs), + ) + log.info('proxy completed', { + kind, + route: proxyRouteTemplate(pathname), + status: response.status, + ...timing, + totalMs, + }) + return response +} + +async function updateSessionInner( + request: NextRequest, + timing: ProxyTimings, +): Promise { let supabaseResponse = NextResponse.next({ request, }) @@ -62,7 +108,7 @@ export async function updateSession(request: NextRequest) { const { data: { user }, error: authError, - } = await supabase.auth.getUser() + } = await timed(timing, 'authMs', () => supabase.auth.getUser()) // Get the pathname const pathname = request.nextUrl.pathname @@ -93,8 +139,12 @@ export async function updateSession(request: NextRequest) { !apiRequestSkipsSessionTimeout(pathname, hasAuthorizationHeader) ) { const encodedState = request.cookies.get(SESSION_TIMEOUT_COOKIE)?.value - const sessionId = await getSupabaseSessionId(supabase) - const verifiedState = await verifySessionTimeoutState(encodedState) + const sessionId = await timed(timing, 'sessionMs', () => + getSupabaseSessionId(supabase), + ) + const verifiedState = await timed(timing, 'sessionMs', () => + verifySessionTimeoutState(encodedState), + ) if (encodedState && !verifiedState) { await signOutTimedOutSession(supabase) @@ -121,7 +171,9 @@ export async function updateSession(request: NextRequest) { const method = isSessionAuthMethod(hintedMethod) ? hintedMethod : 'password' - const autoLogout = await fetchAutoLogoutPreference(supabase, user.id) + const autoLogout = await timed(timing, 'sessionMs', () => + fetchAutoLogoutPreference(supabase, user.id), + ) // Unknown preference (failed read): mint nothing, so no fail-open // snapshot gets persisted; the next request retries the read. @@ -184,8 +236,9 @@ export async function updateSession(request: NextRequest) { hasAuthorizationHeader, ) if (!skipMfaGate && user && shouldEnforceMfa(user)) { - const { data: aal } = - await supabase.auth.mfa.getAuthenticatorAssuranceLevel() + const { data: aal } = await timed(timing, 'mfaMs', () => + supabase.auth.mfa.getAuthenticatorAssuranceLevel(), + ) if (aal?.nextLevel === 'aal2' && aal?.currentLevel === 'aal1') { return NextResponse.json({ error: 'MFA-verifiering krävs.' }, { status: 403 }) } @@ -310,11 +363,15 @@ export async function updateSession(request: NextRequest) { degraded: boolean } | null = null const resolveCompanyOnce = async () => - (resolvedCompany ??= await resolveCompanyForMiddleware(supabase, user.id, request)) + (resolvedCompany ??= await timed(timing, 'companyMs', () => + resolveCompanyForMiddleware(supabase, user.id, request), + )) // MFA enforcement (application-side only, not RLS) if (shouldEnforceMfa(user)) { - const { data: aal } = await supabase.auth.mfa.getAuthenticatorAssuranceLevel() + const { data: aal } = await timed(timing, 'mfaMs', () => + supabase.auth.mfa.getAuthenticatorAssuranceLevel(), + ) // User has MFA enrolled but hasn't verified this session → redirect to verify if (aal?.nextLevel === 'aal2' && aal?.currentLevel === 'aal1') { @@ -325,7 +382,9 @@ export async function updateSession(request: NextRequest) { // Skip for users with no companies (still setting up) const { companyId: companyIdForMfa } = await resolveCompanyOnce() if (companyIdForMfa) { - const { data: factors } = await supabase.auth.mfa.listFactors() + const { data: factors } = await timed(timing, 'mfaMs', () => + supabase.auth.mfa.listFactors(), + ) const hasVerifiedFactor = factors?.totp?.some(f => f.status === 'verified') if (!hasVerifiedFactor) { diff --git a/lib/supabase/proxy-timing.ts b/lib/supabase/proxy-timing.ts new file mode 100644 index 00000000..7e8d946c --- /dev/null +++ b/lib/supabase/proxy-timing.ts @@ -0,0 +1,115 @@ +/** + * Per-request timing for the auth proxy (lib/supabase/middleware.ts). + * + * The proxy runs in front of every page, RSC, prefetch and /api request and + * makes several sequential network calls (Supabase Auth, the active-company + * RPC, MFA factor lookups). Nothing measured that cost until now, while the + * route wrapper (lib/api/with-route-context.ts) has logged authMs/companyMs/ + * handlerMs per API call for months. These helpers give the proxy the same + * Server-Timing header and one structured "proxy completed" log line per + * request so the fixed per-request cost can be read off Vercel logs and the + * browser Timing tab instead of guessed. + * + * Pure functions only: the middleware test suite mocks Supabase heavily, so + * classification and formatting live here where they can be unit-tested + * without that harness. + */ + +export type ProxyRequestKind = 'api' | 'prefetch' | 'rsc' | 'page' + +export interface ProxyTimings { + /** supabase.auth.getUser(): a network round trip to Supabase Auth. */ + authMs: number + /** Session-timeout state: getClaims + HMAC verify + auto_logout read. */ + sessionMs: number + /** resolve_active_company RPC (or the query fallback) incl. write-back. */ + companyMs: number + /** MFA assurance level + listFactors (the latter is a network call). */ + mfaMs: number +} + +export type ProxyTimingKey = keyof ProxyTimings + +/** + * Header used on /api responses. withRouteContext owns `Server-Timing` on + * API routes and only sets it when absent, so the proxy's numbers travel on + * a separate header there; on page/RSC responses nothing else sets + * Server-Timing and the proxy uses the standard header directly. + */ +export const PROXY_TIMING_HEADER = 'X-Proxy-Timing' + +export function createProxyTimings(): ProxyTimings { + return { authMs: 0, sessionMs: 0, companyMs: 0, mfaMs: 0 } +} + +/** Run `fn` and add its wall time to `timing[key]` (accumulates on repeats). */ +export async function timed( + timing: ProxyTimings, + key: ProxyTimingKey, + fn: () => Promise, +): Promise { + const start = Date.now() + try { + return await fn() + } finally { + timing[key] += Date.now() - start + } +} + +/** + * Which kind of request the proxy is fronting. Prefetch and RSC requests + * are recognised by the headers the Next.js app router sends + * (`Next-Router-Prefetch: 1`, `RSC: 1`); header names are case-insensitive + * on the Fetch `Headers` interface, so lower-case lookups are fine. + */ +export function classifyProxyRequest( + pathname: string, + headers: Headers, +): ProxyRequestKind { + if (pathname.startsWith('/api')) return 'api' + if (headers.get('next-router-prefetch') === '1') return 'prefetch' + if (headers.get('rsc') === '1') return 'rsc' + return 'page' +} + +const UUID_RE = + /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i +const NUMERIC_RE = /^\d+$/ +/** Prefixes whose tail is a secret (invite tokens, payslip links, PKCE). */ +const TOKEN_PREFIXES = ['/invite', '/payslip', '/auth'] + +/** + * Collapse a concrete pathname to a loggable route template: UUIDs become + * `:id`, numbers `:n`, long opaque segments `:token`, and paths under the + * token-carrying prefixes are cut to the prefix so a secret never lands in + * a log line. + */ +export function proxyRouteTemplate(pathname: string): string { + for (const prefix of TOKEN_PREFIXES) { + if (pathname === prefix || pathname.startsWith(`${prefix}/`)) { + return `${prefix}/*` + } + } + const segments = pathname.split('/').map((segment) => { + if (segment === '') return segment + if (UUID_RE.test(segment)) return ':id' + if (NUMERIC_RE.test(segment)) return ':n' + if (segment.length >= 24) return ':token' + return segment + }) + return segments.join('/') || '/' +} + +/** `Server-Timing` value: one `mw-*` metric per phase plus the total. */ +export function formatProxyServerTiming( + timing: ProxyTimings, + totalMs: number, +): string { + return [ + `mw-auth;dur=${timing.authMs}`, + `mw-session;dur=${timing.sessionMs}`, + `mw-company;dur=${timing.companyMs}`, + `mw-mfa;dur=${timing.mfaMs}`, + `mw-total;dur=${totalMs}`, + ].join(', ') +} diff --git a/scripts/__tests__/log-percentiles.test.ts b/scripts/__tests__/log-percentiles.test.ts new file mode 100644 index 00000000..0d18b886 --- /dev/null +++ b/scripts/__tests__/log-percentiles.test.ts @@ -0,0 +1,123 @@ +import { describe, it, expect } from 'vitest' +import { + extractRecord, + parseArgs, + percentile, + renderMarkdown, + summarize, +} from '../perf/log-percentiles' + +const opLine = (operation: string, durationMs: number, authMs = 2) => + JSON.stringify({ + level: 'info', + module: `api/${operation}`, + msg: 'op completed', + operation, + durationMs, + authMs, + }) + +describe('extractRecord', () => { + it('parses a bare logger line', () => { + expect(extractRecord(opLine('period.list', 77))).toMatchObject({ + operation: 'period.list', + durationMs: 77, + }) + }) + + it('unwraps the JSON embedded in a vercel logs --json envelope', () => { + const envelope = JSON.stringify({ + timestamp: 1, + source: 'serverless', + requestPath: '/api/bookkeeping/fiscal-periods', + message: ` ${opLine('period.list', 77)}`, + }) + expect(extractRecord(envelope)).toMatchObject({ + source: 'serverless', + operation: 'period.list', + durationMs: 77, + }) + }) + + it('keeps a non-JSON message as the envelope only', () => { + expect(extractRecord(JSON.stringify({ message: 'plain text' }))).toEqual({ + message: 'plain text', + }) + }) + + it('ignores blank and unparseable lines', () => { + expect(extractRecord('')).toBeNull() + expect(extractRecord('not json')).toBeNull() + expect(extractRecord('{broken')).toBeNull() + }) +}) + +describe('percentile', () => { + it('uses nearest rank', () => { + const sorted = [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] + expect(percentile(sorted, 50)).toBe(5) + expect(percentile(sorted, 90)).toBe(9) + expect(percentile(sorted, 99)).toBe(10) + expect(percentile([42], 50)).toBe(42) + expect(Number.isNaN(percentile([], 50))).toBe(true) + }) +}) + +describe('summarize', () => { + const records = [ + { operation: 'a', durationMs: 10, authMs: 1 }, + { operation: 'a', durationMs: 30, authMs: 1 }, + { operation: 'b', durationMs: 100, authMs: 50 }, + { operation: 'b', durationMs: 'oops', authMs: 5 }, + ] + + it('groups by the requested keys and ranks slowest first', () => { + const rows = summarize(records, { fields: ['durationMs', 'authMs'], groupBy: ['operation'] }) + expect(rows.map((r) => r.group)).toEqual(['b', 'a']) + expect(rows[1].count).toBe(2) + expect(rows[1].fields.durationMs).toEqual({ p50: 10, p90: 30, p99: 30, max: 30 }) + // The non-numeric durationMs is skipped for that field but the row still counts the sample. + expect(rows[0].count).toBe(2) + expect(rows[0].fields.durationMs.max).toBe(100) + }) + + it('applies exact-match filters and min-count', () => { + const rows = summarize(records, { + fields: ['durationMs'], + groupBy: ['operation'], + filters: [{ key: 'operation', value: 'a' }], + }) + expect(rows).toHaveLength(1) + expect(rows[0].group).toBe('a') + expect(summarize(records, { fields: ['durationMs'], groupBy: ['operation'], minCount: 3 })).toEqual([]) + }) + + it('produces a single "all" row without grouping', () => { + const rows = summarize(records, { fields: ['durationMs'] }) + expect(rows).toHaveLength(1) + expect(rows[0].group).toBe('all') + expect(rows[0].count).toBe(4) + }) +}) + +describe('renderMarkdown + parseArgs', () => { + it('renders a markdown table with one column set per field', () => { + const rows = summarize([{ k: 'x', v: 5 }], { fields: ['v'], groupBy: ['k'] }) + const md = renderMarkdown(rows, ['v']) + expect(md.split('\n')[0]).toBe('| group | n | v p50 | v p90 | v p99 | v max |') + expect(md).toContain('| x | 1 | 5 | 5 | 5 | 5 |') + }) + + it('parses the documented CLI flags', () => { + expect( + parseArgs(['--field', 'a,b', '--group', 'kind,route', '--filter', 'msg=op completed', '--min-count', '5']), + ).toEqual({ + fields: ['a', 'b'], + groupBy: ['kind', 'route'], + filters: [{ key: 'msg', value: 'op completed' }], + minCount: 5, + }) + expect(() => parseArgs([])).toThrow('--field is required') + expect(() => parseArgs(['--bogus'])).toThrow('unknown option') + }) +}) diff --git a/scripts/perf/README.md b/scripts/perf/README.md new file mode 100644 index 00000000..867eeb3b --- /dev/null +++ b/scripts/perf/README.md @@ -0,0 +1,69 @@ +# Request latency measurement (auth proxy + route wrapper) + +Why this exists: a customer reported that "it takes time before all fields load when clicking around" (2026-08-26). The API handlers themselves are fast (p50 38 ms); the cost is the number of sequential calls a page makes and the fixed per-request tax in front of each one (auth proxy + route wrapper). This page is the protocol for measuring that tax before and after every change in the responsiveness plan, so no PR claims a win without a number. + +## What is instrumented + +| Surface | Where | Header | Log line | +|---|---|---|---| +| Auth proxy (every page, RSC, prefetch, `/api` request) | `lib/supabase/middleware.ts` via `lib/supabase/proxy-timing.ts` | `Server-Timing: mw-auth, mw-session, mw-company, mw-mfa, mw-total` on page/RSC/prefetch responses; `X-Proxy-Timing` (same value) on `/api` responses | `proxy completed` with `kind` (`page`, `rsc`, `prefetch`, `api`), `route` (ids and tokens collapsed), `status`, `authMs`, `sessionMs`, `companyMs`, `mfaMs`, `totalMs` | +| Route wrapper (`withRouteContext`, 367 of 529 routes) | `lib/api/with-route-context.ts` | `Server-Timing: auth, company, handler` | `op completed` with `operation`, `status`, `durationMs`, `authMs`, `companyMs`, `handlerMs` | +| Browser | `@vercel/speed-insights` mounted in `app/layout.tsx` | n/a | Vercel dashboard > Speed Insights > Routes (p75 TTFB, FCP, LCP, INP, CLS per route) | + +Phase meanings for the proxy: `authMs` = `supabase.auth.getUser()` (a network call to Supabase Auth); `sessionMs` = session-timeout cookie state (`getClaims`, HMAC verify, `auto_logout` read when re-minting); `companyMs` = `resolve_active_company` RPC including the write-back on fallback; `mfaMs` = assurance-level check plus `listFactors()` (a second network call) on the enforced-MFA path. + +## Reading the numbers + +Percentiles per route from production logs (the `vercel` CLI is linked to the project; `--limit` defaults to 100, raise it): + +```bash +# route wrapper, grouped by operation +vercel logs --environment production --since 24h --limit 1000 --json --query "op completed" \ + | npx tsx scripts/perf/log-percentiles.ts --field durationMs,authMs,companyMs,handlerMs --group operation + +# auth proxy, grouped by request kind and route +vercel logs --environment production --since 24h --limit 1000 --json --query "proxy completed" \ + | npx tsx scripts/perf/log-percentiles.ts --field totalMs,authMs,sessionMs,companyMs,mfaMs --group kind,route + +# auth proxy, one row per kind (the headline fixed cost) +vercel logs --environment production --since 24h --limit 1000 --json --query "proxy completed" \ + | npx tsx scripts/perf/log-percentiles.ts --field totalMs,authMs,companyMs,mfaMs --group kind +``` + +If `--limit` above 100 is not honoured by the installed CLI, loop `--since`/`--until` windows and concatenate before piping. The Vercel MCP `get_runtime_logs` tool (`group_by: route`) gives request counts per route, not percentiles; use it for prefetch volume (`kind=prefetch` per page load). + +In the browser: DevTools > Network, pick a document or `_rsc` request, Timing tab, the `mw-*` metrics show the proxy phases; `/api` responses show `auth`/`company`/`handler` from the route wrapper and the proxy numbers in the `X-Proxy-Timing` response header. + +Request count per interaction (the number that maps to "fields load late"), in the console after each action on a production build (`next build && next start`): + +```js +performance.getEntriesByType('resource') + .filter((r) => /\/api\/|\/rest\/v1\//.test(r.name)) + .map((r) => `${Math.round(r.startTime)} ${Math.round(r.duration)}ms ${r.name}`) +``` + +Interactions to record every time: `/transactions` soft navigation; open Bokför on a row; `/bookkeeping` then Nytt verifikat; `/invoices` then Ny faktura; `/reports`; `/supplier-invoices/new`; a list row to its detail page on customers and invoices. Note the request count and how many dependent rounds (start times that wait on an earlier response). + +## Targets (p75 unless stated) + +| Metric | Target | Why | +|---|---|---| +| Proxy `page`/`rsc` totalMs | p50 < 40 ms, p90 < 100 ms | Two parallel DB waves at most, no auth network call | +| Proxy `api` totalMs | p50 < 5 ms | Local JWT verification only | +| Route wrapper auth + company | p50 < 45 ms (read), same for write | One company resolution per call, never two | +| TTFB (hard load) | < 400 ms | Layout on two DB waves | +| LCP | < 1.5 s | | +| INP | < 200 ms | The metric "clicking around" maps to | +| Reference-data requests per form open | 0 blocking | Seeded and cached client-side | + +## Protocol per PR + +1. Before merging: record the current numbers for the interactions above on a production build, and the last 24 h of `proxy completed` / `op completed` percentiles, in the PR description. +2. 24 h after the production deploy: re-run the same three commands and the same interactions; append one row per PR to the table below. +3. A PR that claims a latency win without a before/after row is not done. + +## Baseline and results + +| Date | Change | Proxy page p50/p90 | Proxy api p50/p90 | Route auth+company p50 | Notes | +|---|---|---|---|---|---| +| 2026-08-26 | Route wrapper only (proxy unmeasured) | n/a | n/a | 44 ms (auth 3, company 41) | 100-call sample; handler p50 38 ms, total p50 96 ms, p90 274 ms | diff --git a/scripts/perf/log-percentiles.ts b/scripts/perf/log-percentiles.ts new file mode 100644 index 00000000..2868eb3f --- /dev/null +++ b/scripts/perf/log-percentiles.ts @@ -0,0 +1,205 @@ +/** + * Percentiles over structured log lines. + * + * Reads JSON Lines on stdin (the shape `vercel logs --json` emits, or raw + * logger output) and prints a markdown table of count / p50 / p90 / p99 / + * max per group for the numeric fields asked for. Used for the + * "op completed" lines from lib/api/with-route-context.ts and the + * "proxy completed" lines from lib/supabase/middleware.ts. + * + * vercel logs --environment production --since 24h --limit 1000 --json \ + * --query "op completed" \ + * | npx tsx scripts/perf/log-percentiles.ts \ + * --field durationMs,authMs,companyMs,handlerMs --group operation + * + * vercel logs --environment production --since 24h --limit 1000 --json \ + * --query "proxy completed" \ + * | npx tsx scripts/perf/log-percentiles.ts \ + * --field totalMs,authMs,companyMs,mfaMs --group kind,route + * + * Options: --field a,b (required), --group x,y (default: none, one row), + * --filter key=value (repeatable; exact match on the parsed record), + * --min-count N (drop groups with fewer samples, default 1). + * + * No dependencies on purpose: this must run from a clean checkout. + */ + +export type LogRecord = Record + +/** + * Turn one input line into a flat record. `vercel logs --json` wraps the + * application line in a `message` (or `text`) string, so an embedded JSON + * object inside that string is parsed and merged over the envelope; a bare + * JSON logger line is used as-is. Unparseable lines yield null. + */ +export function extractRecord(line: string): LogRecord | null { + const trimmed = line.trim() + if (!trimmed.startsWith('{')) return null + let envelope: LogRecord + try { + envelope = JSON.parse(trimmed) as LogRecord + } catch { + return null + } + const message = envelope.message ?? envelope.text + if (typeof message === 'string') { + const start = message.indexOf('{') + if (start >= 0) { + try { + const embedded = JSON.parse(message.slice(start)) as LogRecord + return { ...envelope, ...embedded } + } catch { + // Not a JSON payload: fall through and use the envelope alone. + } + } + } + return envelope +} + +/** Nearest-rank percentile on an ascending-sorted array. */ +export function percentile(sorted: number[], p: number): number { + if (sorted.length === 0) return Number.NaN + const rank = Math.ceil((p / 100) * sorted.length) + return sorted[Math.min(sorted.length, Math.max(1, rank)) - 1] +} + +export interface FieldStats { + p50: number + p90: number + p99: number + max: number +} + +export interface GroupRow { + group: string + count: number + fields: Record +} + +export interface SummarizeOptions { + fields: string[] + groupBy?: string[] + filters?: Array<{ key: string; value: string }> + minCount?: number +} + +function matchesFilters(record: LogRecord, filters: SummarizeOptions['filters']): boolean { + if (!filters || filters.length === 0) return true + return filters.every(({ key, value }) => String(record[key]) === value) +} + +export function summarize(records: LogRecord[], options: SummarizeOptions): GroupRow[] { + const groupBy = options.groupBy ?? [] + const minCount = options.minCount ?? 1 + const buckets = new Map }>() + + for (const record of records) { + if (!matchesFilters(record, options.filters)) continue + const groupKey = groupBy.length + ? groupBy.map((key) => String(record[key] ?? '')).join(' / ') + : 'all' + let bucket = buckets.get(groupKey) + if (!bucket) { + bucket = { + count: 0, + values: Object.fromEntries(options.fields.map((f) => [f, [] as number[]])), + } + buckets.set(groupKey, bucket) + } + bucket.count += 1 + for (const field of options.fields) { + const value = record[field] + if (typeof value === 'number' && Number.isFinite(value)) bucket.values[field].push(value) + } + } + + const rows: GroupRow[] = [] + for (const [group, bucket] of buckets) { + const count = bucket.count + if (count < minCount) continue + const fields: Record = {} + for (const field of options.fields) { + const sorted = [...bucket.values[field]].sort((a, b) => a - b) + fields[field] = { + p50: percentile(sorted, 50), + p90: percentile(sorted, 90), + p99: percentile(sorted, 99), + max: sorted.length ? sorted[sorted.length - 1] : Number.NaN, + } + } + rows.push({ group, count, fields }) + } + + // Slowest first by the first field's p50 so the table reads as a ranking. + const primary = options.fields[0] + rows.sort((a, b) => (b.fields[primary]?.p50 ?? 0) - (a.fields[primary]?.p50 ?? 0)) + return rows +} + +function fmt(n: number): string { + return Number.isNaN(n) ? '-' : String(Math.round(n)) +} + +export function renderMarkdown(rows: GroupRow[], fields: string[]): string { + const header = ['group', 'n', ...fields.flatMap((f) => [`${f} p50`, `${f} p90`, `${f} p99`, `${f} max`])] + const lines = [ + `| ${header.join(' | ')} |`, + `|${header.map(() => '---').join('|')}|`, + ] + for (const row of rows) { + const cells = [row.group, String(row.count)] + for (const field of fields) { + const s = row.fields[field] + cells.push(fmt(s.p50), fmt(s.p90), fmt(s.p99), fmt(s.max)) + } + lines.push(`| ${cells.join(' | ')} |`) + } + return lines.join('\n') +} + +export function parseArgs(argv: string[]): SummarizeOptions { + const options: SummarizeOptions = { fields: [], groupBy: [], filters: [], minCount: 1 } + for (let i = 0; i < argv.length; i += 1) { + const arg = argv[i] + const next = () => { + i += 1 + const value = argv[i] + if (value === undefined) throw new Error(`${arg} needs a value`) + return value + } + if (arg === '--field') options.fields = next().split(',').filter(Boolean) + else if (arg === '--group') options.groupBy = next().split(',').filter(Boolean) + else if (arg === '--filter') { + const [key, ...rest] = next().split('=') + options.filters!.push({ key, value: rest.join('=') }) + } else if (arg === '--min-count') options.minCount = Number(next()) + else throw new Error(`unknown option ${arg}`) + } + if (options.fields.length === 0) throw new Error('--field is required') + return options +} + +async function readStdin(): Promise { + const chunks: Buffer[] = [] + for await (const chunk of process.stdin) chunks.push(chunk as Buffer) + return Buffer.concat(chunks).toString('utf8') +} + +async function main(): Promise { + const options = parseArgs(process.argv.slice(2)) + const input = await readStdin() + const records = input + .split('\n') + .map(extractRecord) + .filter((r): r is LogRecord => r !== null) + const rows = summarize(records, options) + process.stdout.write(`${records.length} records parsed\n\n`) + process.stdout.write(`${renderMarkdown(rows, options.fields)}\n`) +} + +if (process.argv[1] && /log-percentiles\.(?:ts|mts|js|mjs)$/.test(process.argv[1])) { + main().catch((err) => { + console.error(err instanceof Error ? err.message : err) + process.exit(1) + }) +}