diff --git a/.changeset/server-timing-perf-spans-2408.md b/.changeset/server-timing-perf-spans-2408.md new file mode 100644 index 0000000000..a9f86aaf0a --- /dev/null +++ b/.changeset/server-timing-perf-spans-2408.md @@ -0,0 +1,19 @@ +--- +"@objectstack/observability": patch +"@objectstack/driver-sql": patch +"@objectstack/runtime": patch +"@objectstack/plugin-hono-server": patch +--- + +feat(observability): decompose `Server-Timing` into auth / db / hooks / serialize spans (perf-tuning mode) + +The opt-in `Server-Timing` header now breaks a request's server time into the phases that actually explain it, so an operator can open DevTools → Network → Timing and see where the time went without standing up an external tracing backend: + +- **`db`** — total SQL time with a **query count**. The SQL driver wires knex's `query` / `query-response` events (keyed by `__knexQueryUid`) and folds each query into one aggregate member (`db;dur=210;desc="6 queries"`) — the query count is the number most useful for spotting N sequential round-trips. Timing is attributed to the originating request via `AsyncLocalStorage`, so it is correct under concurrency and never cross-attributes. SQL text is never emitted, only durations and a count. +- **`auth`** — identity / session resolution in the dispatcher, the prime suspect for unexplained data-API overhead. +- **`hooks`** — total business-hook execution time with a hook count, fed through the engine's existing `HookMetricsRecorder` seam (wired from the runtime, so `@objectstack/objectql`'s lean `core` tier stays observability-free). +- **`serialize`** — response JSON encoding in the HTTP adapter. + +Adds `countServerTiming(name, dur, unit)` (and `PerfTiming.count`) to fold high-frequency phases into a single aggregate member instead of flooding the header. Every phase is a no-op when perf-tuning is off (`serverTiming: true` / `OS_SERVER_TIMING=true`), so there is zero measurable overhead on the normal path. + +Closes #2408. diff --git a/docs/OBSERVABILITY.md b/docs/OBSERVABILITY.md index 03f0b7e6c3..0756e56d1a 100644 --- a/docs/OBSERVABILITY.md +++ b/docs/OBSERVABILITY.md @@ -229,9 +229,15 @@ phases inline, which makes it trivial to see where wall-clock time went on a slow request without attaching a profiler. ``` -Server-Timing: total;dur=18.7;desc="Total server time", parse;dur=0.4;desc="Body parse", handler;dur=17.9;desc="Route handler" +Server-Timing: parse;dur=0.4;desc="Body parse", auth;dur=42;desc="Identity/session", db;dur=210;desc="6 queries", hooks;dur=18;desc="3 hooks", serialize;dur=7;desc="Response serialize", handler;dur=280;desc="Route handler", total;dur=355;desc="Total server time" ``` +Reading it: the request spent 42ms resolving identity, 210ms across **6** SQL +queries (the count is the number to watch — six sequential round-trips is the +usual culprit behind an inexplicably slow list), 18ms in **3** business hooks, +and 7ms serializing the response. `db` and `hooks` are aggregates — one member +carrying the summed duration and the event count, not one member per query. + This is **off by default**: the header discloses internal phase durations, which is helpful for profiling but also lets a caller fingerprint the backend. Treat it as a perf-tuning toggle you flip in staging (or briefly in production @@ -251,9 +257,23 @@ OS_SERVER_TIMING=true os serve ``` When enabled, every response carries `total` (the whole request, measured by -an outer middleware) plus any sub-phases the request recorded. The HTTP adapter -contributes `parse` (request-body parsing) and `handler` (route-handler -execution) out of the box. +an outer middleware) plus the sub-phases the request path records out of the +box: + +| Member | Recorded by | Meaning | +|:---|:---|:---| +| `total` | Hono server middleware | Whole request, wall-clock. | +| `parse` | HTTP adapter | Request-body parsing. | +| `handler` | HTTP adapter | Route-handler execution. | +| `serialize` | HTTP adapter | Response JSON encoding. | +| `auth` | Dispatcher | Identity / session resolution — the prime suspect for unexplained data-API overhead. | +| `db` | SQL driver | Total SQL time across the request; `desc` is the **query count** (folded from knex's per-query events, attributed to the originating request via `AsyncLocalStorage` so it is correct under concurrency). SQL text is never emitted. | +| `hooks` | ObjectQL engine | Total business-hook execution time; `desc` is the hook count. | + +Each phase is recorded through a request-scoped collector that is a no-op when +the mode is off, so every one of them costs nothing on the normal path. The +`db` / `hooks` aggregates fold high-frequency events into a single member via +`countServerTiming` (below) rather than emitting one member per event. ### Recording your own phases @@ -271,6 +291,16 @@ const rows = await measureServerTiming('db', () => engine.find(query), 'Primary `startServerTiming(name)` (returns an `end()` callback) and `recordServerTiming(name, dur)` are also available for manual instrumentation. +For a phase that fires many times per request (per query, per hook), use +`countServerTiming(name, dur, unit)` — it folds every call into one aggregate +member `name;dur=;desc=" "` instead of flooding the header: + +```ts +import { countServerTiming } from '@objectstack/observability'; + +// each call adds to the running total + count for `db` +countServerTiming('db', queryMs, 'queries'); // → db;dur=;desc=" queries" +``` ## Go-live checklist diff --git a/packages/observability/src/index.ts b/packages/observability/src/index.ts index 0f05701ea0..8fbc4c589c 100644 --- a/packages/observability/src/index.ts +++ b/packages/observability/src/index.ts @@ -51,5 +51,6 @@ export { recordServerTiming, startServerTiming, measureServerTiming, + countServerTiming, type ServerTimingMark, } from './perf-timing.js'; diff --git a/packages/observability/src/perf-timing.test.ts b/packages/observability/src/perf-timing.test.ts index 74de6b61e4..f5c1ba66d3 100644 --- a/packages/observability/src/perf-timing.test.ts +++ b/packages/observability/src/perf-timing.test.ts @@ -9,6 +9,7 @@ import { recordServerTiming, startServerTiming, measureServerTiming, + countServerTiming, } from './perf-timing.js'; describe('formatServerTiming', () => { @@ -102,6 +103,49 @@ describe('PerfTiming', () => { expect(t.marks()).toHaveLength(1); expect(t.marks()[0].name).toBe('boom'); }); + + describe('count() aggregate', () => { + it('folds repeated events into one mark carrying total + count', () => { + const t = new PerfTiming(); + t.count('db', 10, 'queries'); + t.count('db', 5, 'queries'); + t.count('db', 3, 'queries'); + expect(t.marks()).toHaveLength(1); + expect(t.toHeader()).toBe('db;dur=18;desc="3 queries"'); + }); + + it('keeps the aggregate at its first-seen position (before a later total)', () => { + const t = new PerfTiming(); + t.count('db', 4, 'queries'); + t.record('total', 20, 'Total server time'); + t.count('db', 6, 'queries'); // still folds into the first db mark + expect(t.marks().map((m) => m.name)).toEqual(['db', 'total']); + expect(t.toHeader()).toBe('db;dur=10;desc="2 queries", total;dur=20;desc="Total server time"'); + }); + + it('tracks independent names separately', () => { + const t = new PerfTiming(); + t.count('db', 10, 'queries'); + t.count('hooks', 2, 'hooks'); + t.count('hooks', 3, 'hooks'); + expect(t.toHeader()).toBe('db;dur=10;desc="1 queries", hooks;dur=5;desc="2 hooks"'); + }); + + it('emits a bare count when no unit is given', () => { + const t = new PerfTiming(); + t.count('x', 1); + t.count('x', 1); + expect(t.toHeader()).toBe('x;dur=2;desc="2"'); + }); + + it('ignores non-finite / negative durations but still counts the event', () => { + const t = new PerfTiming(); + t.count('db', Number.NaN, 'queries'); + t.count('db', -5, 'queries'); + t.count('db', 7, 'queries'); + expect(t.toHeader()).toBe('db;dur=7;desc="3 queries"'); + }); + }); }); describe('ambient collector', () => { @@ -113,10 +157,34 @@ describe('ambient collector', () => { recordServerTiming('x', 1); // must not throw const end = startServerTiming('y'); end(); // must not throw + countServerTiming('db', 1, 'queries'); // must not throw const v = await measureServerTiming('z', async () => 7); expect(v).toBe(7); }); + it('countServerTiming folds onto the ambient collector', async () => { + const t = new PerfTiming(); + await runWithPerfTiming(t, async () => { + countServerTiming('db', 4, 'queries'); + await new Promise((r) => setTimeout(r, 1)); + countServerTiming('db', 6, 'queries'); // after an await — same ALS scope + }); + expect(t.toHeader()).toBe('db;dur=10;desc="2 queries"'); + }); + + it('pins the ambient store to a global-registry symbol (shared across module copies)', () => { + // The store MUST live on globalThis under Symbol.for so that a second + // copy of this module (ESM vs CJS build, or an inlined bundle) shares it + // — otherwise cross-layer spans (db/auth/hooks recorded from the SQL + // driver / engine) never reach the collector the HTTP server opened. + const key = Symbol.for('@objectstack/observability:perf-timing-store'); + expect((globalThis as Record)[key]).toBeDefined(); + // And the ambient free functions must read THAT store. + const t = new PerfTiming(); + runWithPerfTiming(t, () => recordServerTiming('shared', 1)); + expect(t.marks().map((m) => m.name)).toContain('shared'); + }); + it('records onto the ambient collector inside runWithPerfTiming', async () => { const t = new PerfTiming(); await runWithPerfTiming(t, async () => { diff --git a/packages/observability/src/perf-timing.ts b/packages/observability/src/perf-timing.ts index dbb40ac920..58bc5de44b 100644 --- a/packages/observability/src/perf-timing.ts +++ b/packages/observability/src/perf-timing.ts @@ -17,9 +17,12 @@ * 2. **Ambient collector.** Run a request inside {@link runWithPerfTiming} * and any framework code on that async call chain records phases via the * free functions ({@link measureServerTiming}, {@link startServerTiming}, - * {@link recordServerTiming}) without threading the request object - * through every layer. When no collector is active the free functions are - * cheap no-ops, so call sites pay nothing when the feature is off. + * {@link recordServerTiming}, {@link countServerTiming}) without threading + * the request object through every layer. When no collector is active the + * free functions are cheap no-ops, so call sites pay nothing when the + * feature is off. High-frequency phases (per SQL query, per hook) use + * {@link countServerTiming} to fold into one aggregate mark carrying a + * total duration and an event count. * * `Server-Timing` exposes internal phase durations to any client, which is a * (mild) information-disclosure surface - it helps an attacker profile the @@ -129,6 +132,12 @@ export function formatServerTiming(marks: readonly ServerTimingMark[]): string { */ export class PerfTiming { private readonly _marks: ServerTimingMark[] = []; + /** + * Live aggregate marks by name (see {@link count}). Lazily created so a + * request that never aggregates pays nothing. Each entry points at a mark + * already inserted into {@link _marks}, mutated in place as events arrive. + */ + private _aggregates?: Map; /** Record an already-measured phase. */ record(name: string, dur: number, desc?: string): void { @@ -160,6 +169,38 @@ export class PerfTiming { } } + /** + * Accumulate a repeated sub-phase into a SINGLE aggregate mark. Each call + * adds `dur` to the running total for `name` and increments a counter; the + * mark serializes as `name;dur=;desc=" "` (or just the + * bare count when no `unit` is given). + * + * Use this for high-frequency phases — one SQL query, one hook execution — + * where recording a distinct mark per event would blow the header out to + * hundreds of entries. The single `db;dur=210;desc="6 queries"` member is + * both the total DB time and the query count, which is the number most + * useful for spotting N sequential round-trips. + * + * The aggregate mark is inserted into the record stream the first time its + * name is seen, so it keeps its natural position relative to explicit marks + * (e.g. before the outer `total`, which is recorded last). + */ + count(name: string, dur: number, unit?: string): void { + const add = Number.isFinite(dur) && dur > 0 ? dur : 0; + const aggregates = (this._aggregates ??= new Map()); + let entry = aggregates.get(name); + if (!entry) { + const mark: ServerTimingMark = { name, dur: 0 }; + entry = { mark, count: 0, unit }; + aggregates.set(name, entry); + this._marks.push(mark); + } + entry.count += 1; + entry.mark.dur += add; + if (unit) entry.unit = unit; + entry.mark.desc = entry.unit ? `${entry.count} ${entry.unit}` : String(entry.count); + } + /** Snapshot of recorded marks, in record order. */ marks(): readonly ServerTimingMark[] { return this._marks; @@ -173,7 +214,25 @@ export class PerfTiming { // --- Ambient (request-scoped) collector ------------------------------- -const store = new AsyncLocalStorage(); +/** + * The ambient collector lives in ONE process-wide `AsyncLocalStorage`, pinned + * to a global-registry symbol rather than a plain module-level `const`. + * + * Why: this module is consumed from many packages and can legitimately be + * loaded more than once in a single process — the ESM build (`dist/index.js`) + * and the CJS build (`dist/index.cjs`) are distinct module instances, and a + * bundler may inline yet another copy. A plain `const store` would give each + * copy its OWN store, so a request scope opened through one copy (the HTTP + * server's `runWithPerfTiming`) would be invisible to code reading the ambient + * collector through another copy (the SQL driver, the ObjectQL engine) — the + * cross-layer `db` / `auth` / `hooks` spans would silently never record. + * `Symbol.for` resolves to the same symbol across every copy, so they all share + * the one store. + */ +const STORE_KEY = Symbol.for('@objectstack/observability:perf-timing-store'); +const globalStore = globalThis as unknown as Record | undefined>; +const store: AsyncLocalStorage = + globalStore[STORE_KEY] ?? (globalStore[STORE_KEY] = new AsyncLocalStorage()); /** Run `fn` with `timing` as the ambient collector for the async call chain. */ export function runWithPerfTiming(timing: PerfTiming, fn: () => T): T { @@ -214,3 +273,13 @@ export async function measureServerTiming( if (!t) return fn(); return t.measure(name, fn, desc); } + +/** + * Accumulate a repeated sub-phase (one SQL query, one hook execution) onto the + * ambient collector — see {@link PerfTiming.count}. A no-op when no collector is + * active, so the hot-path call sites (the SQL driver's query listener, the hook + * runner) pay only a single `AsyncLocalStorage` lookup when perf-tuning is off. + */ +export function countServerTiming(name: string, dur: number, unit?: string): void { + store.getStore()?.count(name, dur, unit); +} diff --git a/packages/plugins/driver-sql/package.json b/packages/plugins/driver-sql/package.json index bbe55fc575..1c9a603a85 100644 --- a/packages/plugins/driver-sql/package.json +++ b/packages/plugins/driver-sql/package.json @@ -19,6 +19,7 @@ }, "dependencies": { "@objectstack/core": "workspace:*", + "@objectstack/observability": "workspace:*", "@objectstack/spec": "workspace:*", "@objectstack/types": "workspace:*", "knex": "^3.3.0", diff --git a/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts b/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts new file mode 100644 index 0000000000..cfedf1e385 --- /dev/null +++ b/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts @@ -0,0 +1,103 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, beforeEach, afterEach } from 'vitest'; +import { PerfTiming, runWithPerfTiming, type ServerTimingMark } from '@objectstack/observability'; +import { SqlDriver } from '../src/index.js'; + +/** + * Per-query SQL timing → Server-Timing `db` span (perf-tuning mode). + * + * The driver wires knex's `query` / `query-response` events into the ambient + * request collector so every request's response can report total DB time and a + * query count. These tests assert the wiring itself: attribution is correct + * under concurrency (ALS, not a global counter) and it costs nothing when off. + */ +describe('SqlDriver Server-Timing db span', () => { + let driver: SqlDriver; + let knexInstance: any; + + beforeEach(async () => { + driver = new SqlDriver({ + client: 'better-sqlite3', + connection: { filename: ':memory:' }, + useNullAsDefault: true, + }); + knexInstance = (driver as any).knex; + await knexInstance.schema.createTable('orders', (t: any) => { + t.string('id').primary(); + t.string('customer'); + t.string('status'); + }); + await knexInstance('orders').insert([ + { id: '1', customer: 'Alice', status: 'open' }, + { id: '2', customer: 'Bob', status: 'closed' }, + ]); + }); + + afterEach(async () => { + await knexInstance.destroy(); + }); + + const dbMark = (t: PerfTiming): ServerTimingMark | undefined => + t.marks().find((m) => m.name === 'db'); + + it('records a db mark with a query count for a real find()', async () => { + const t = new PerfTiming(); + const rows = await runWithPerfTiming(t, () => + driver.find('orders', { where: { status: 'open' } }), + ); + expect(rows).toHaveLength(1); + const mark = dbMark(t); + expect(mark).toBeDefined(); + expect(mark!.dur).toBeGreaterThanOrEqual(0); + // find issues at least the SELECT; the mark folds however many it ran. + expect(mark!.desc).toMatch(/^\d+ queries$/); + expect(t.toHeader()).toContain('db;dur='); + }); + + it('folds N raw queries into one aggregate with count N', async () => { + const t = new PerfTiming(); + await runWithPerfTiming(t, async () => { + await knexInstance('orders').select('*'); + await knexInstance('orders').where({ status: 'open' }).select('*'); + await knexInstance('orders').count({ n: '*' }); + }); + expect(dbMark(t)?.desc).toBe('3 queries'); + }); + + it('attributes queries to the originating request under concurrency (ALS, not globals)', async () => { + const tA = new PerfTiming(); + const tB = new PerfTiming(); + // Interleave two "requests": A runs 3 queries, B runs 2, awaiting a + // macrotask between each so the two async chains actually overlap. + const tick = () => new Promise((r) => setTimeout(r, 0)); + await Promise.all([ + runWithPerfTiming(tA, async () => { + await knexInstance('orders').select('id'); + await tick(); + await knexInstance('orders').select('id'); + await tick(); + await knexInstance('orders').select('id'); + }), + runWithPerfTiming(tB, async () => { + await tick(); + await knexInstance('orders').select('customer'); + await tick(); + await knexInstance('orders').select('customer'); + }), + ]); + expect(dbMark(tA)?.desc).toBe('3 queries'); + expect(dbMark(tB)?.desc).toBe('2 queries'); + }); + + it('is a no-op with zero overhead when no collector is active', async () => { + // No runWithPerfTiming scope → currentPerfTiming() is undefined. + await expect(knexInstance('orders').select('*')).resolves.toBeDefined(); + // A subsequent in-scope query still records correctly (no stale state). + const t = new PerfTiming(); + await runWithPerfTiming(t, async () => { + await knexInstance('orders').select('*'); + }); + expect(dbMark(t)?.desc).toBe('1 queries'); + }); +}); diff --git a/packages/plugins/driver-sql/src/sql-driver.ts b/packages/plugins/driver-sql/src/sql-driver.ts index dffa932d78..086841a038 100644 --- a/packages/plugins/driver-sql/src/sql-driver.ts +++ b/packages/plugins/driver-sql/src/sql-driver.ts @@ -24,6 +24,7 @@ import { import knex, { Knex } from 'knex'; import { nanoid } from 'nanoid'; import { createHash } from 'node:crypto'; +import { currentPerfTiming, perfNow, type PerfTiming } from '@objectstack/observability'; /** * Default ID length for auto-generated IDs. @@ -541,6 +542,48 @@ export class SqlDriver implements IDataDriver { this.autoMigrate = autoMigrate ?? 'off'; this.config = knexConfig; this.knex = knex(knexConfig); + this.installQueryTiming(); + } + + /** + * Per-request SQL query timing (perf-tuning mode). Correlates knex's + * `query` → `query-response` / `query-error` events by `__knexQueryUid` and + * folds each query's wall time into the ambient request collector's `db` + * aggregate — one `Server-Timing` member carrying total DB time **and** a + * query count, the number most useful for spotting N sequential round-trips + * in DevTools → Network → Timing. + * + * Attribution is captured at `query` time, which runs inside the initiating + * request's `AsyncLocalStorage` scope (knex emits it synchronously from the + * runner after connection acquisition, still on the awaited call chain), so + * concurrent requests never cross-attribute. When perf-tuning is off, + * {@link currentPerfTiming} is `undefined` and the listener returns at once — + * nothing is tracked and the map stays empty, so the cost is a single ALS + * lookup per query. + * + * Only durations and a count are recorded — never SQL text — so the header + * can be surfaced without leaking query shapes to non-admins. + */ + private installQueryTiming(): void { + // uid → { start, collector }, populated only while a collector is active, + // and always removed when the query settles (bounded by in-flight queries). + const inflight = new Map(); + this.knex.on('query', (q: any) => { + const timing = currentPerfTiming(); + if (!timing) return; + const uid = q?.__knexQueryUid; + if (typeof uid === 'string') inflight.set(uid, { t0: perfNow(), timing }); + }); + const settle = (q: any): void => { + const uid = q?.__knexQueryUid; + if (typeof uid !== 'string') return; + const rec = inflight.get(uid); + if (!rec) return; + inflight.delete(uid); + rec.timing.count('db', perfNow() - rec.t0, 'queries'); + }; + this.knex.on('query-response', (_response: any, q: any) => settle(q)); + this.knex.on('query-error', (_error: any, q: any) => settle(q)); } /** diff --git a/packages/plugins/plugin-hono-server/src/adapter.ts b/packages/plugins/plugin-hono-server/src/adapter.ts index 245eaf206e..d7243e0d49 100644 --- a/packages/plugins/plugin-hono-server/src/adapter.ts +++ b/packages/plugins/plugin-hono-server/src/adapter.ts @@ -146,7 +146,14 @@ export class HonoHttpServer implements IHttpServer { }; const res = { - json: (data: any) => { capturedResponse = c.json(data); }, + json: (data: any) => { + // `serialize` Server-Timing span — JSON-encoding the body is + // the one adapter-owned cost between "handler done" and + // "bytes on the wire". No-op when perf-tuning is off. + const endSerialize = _perf?.start('serialize', 'Response serialize'); + capturedResponse = c.json(data); + endSerialize?.(); + }, send: (data: string | Uint8Array | ArrayBuffer | Buffer) => { if (data instanceof Uint8Array || data instanceof ArrayBuffer || (typeof Buffer !== 'undefined' && Buffer.isBuffer?.(data))) { const body = data instanceof ArrayBuffer ? data : (data as Uint8Array).buffer.slice((data as Uint8Array).byteOffset, (data as Uint8Array).byteOffset + (data as Uint8Array).byteLength); diff --git a/packages/plugins/plugin-hono-server/src/server-timing.test.ts b/packages/plugins/plugin-hono-server/src/server-timing.test.ts index 4d0c99dca8..2369087022 100644 --- a/packages/plugins/plugin-hono-server/src/server-timing.test.ts +++ b/packages/plugins/plugin-hono-server/src/server-timing.test.ts @@ -2,6 +2,7 @@ import { describe, it, expect, beforeEach, afterEach } from 'vitest'; import { HonoServerPlugin } from './hono-plugin'; +import { countServerTiming } from '@objectstack/observability'; import type { PluginContext } from '@objectstack/core'; /** @@ -49,12 +50,29 @@ describe('Server-Timing (perf-tuning) middleware', () => { expect(res.status).toBe(200); const header = res.headers.get('Server-Timing'); expect(header).toBeTruthy(); - // total is always present; the adapter contributes parse + handler. + // total is always present; the adapter contributes parse + handler, + // and serialize (the /ping handler calls res.json). expect(header).toMatch(/(^|, )total;dur=[\d.]+/); expect(header).toContain('handler;dur='); + expect(header).toContain('serialize;dur='); expect(await res.json()).toEqual({ ok: true }); }); + it('folds request-scoped aggregate spans (e.g. db query count) into the header', async () => { + const { server, app } = await setup({ serverTiming: true }); + // Simulate the SQL driver recording two per-query timings for this request. + server.get('/agg', (_req: any, res: any) => { + countServerTiming('db', 4, 'queries'); + countServerTiming('db', 6, 'queries'); + return res.json({ ok: true }); + }); + const res = await app.request('/agg'); + const header = res.headers.get('Server-Timing'); + expect(header).toBeTruthy(); + // One aggregate member carrying summed duration + event count — not two. + expect(header).toContain('db;dur=10;desc="2 queries"'); + }); + it('is enabled via OS_SERVER_TIMING=true when the option is unset', async () => { process.env.OS_SERVER_TIMING = 'true'; const { app } = await setup(); diff --git a/packages/runtime/src/app-plugin.ts b/packages/runtime/src/app-plugin.ts index bf03526622..f21849319c 100644 --- a/packages/runtime/src/app-plugin.ts +++ b/packages/runtime/src/app-plugin.ts @@ -8,6 +8,7 @@ import { loadDisabledPackageIds } from './package-state-store.js'; import type { IMetadataService, II18nService } from '@objectstack/spec/contracts'; import { QuickJSScriptRunner } from './sandbox/quickjs-runner.js'; import { hookBodyRunnerFactory, actionBodyRunnerFactory } from './sandbox/body-runner.js'; +import { countServerTiming } from '@objectstack/observability'; /** * Optional per-project context attached when AppPlugin is instantiated by the @@ -122,6 +123,11 @@ export class AppPlugin implements Plugin { // Same for the action runner — authored actions register in Phase 2's // authored-action re-sync and need the sandbox bridge in place (#2605). this.installDefaultActionBodyRunner(ctx); + // Feed per-hook execution time into the request-scoped perf collector + // so the `Server-Timing` header can split "hook time" from "DB time". + // Same boot point as the runners so it is in place before Phase 2 binds + // metadata-service hooks; a no-op unless perf-tuning is on. + this.installHookMetricsTiming(ctx); // Wire the authored-translation sync (#2591) — also BEFORE the empty-env // return: an empty env is exactly where a user authors their first // Studio translation. Covers whatever `i18n` service this kernel ends @@ -268,6 +274,47 @@ export class AppPlugin implements Plugin { ctx.logger.info('[AppPlugin] Installed default action body runner (runtime-authored actions can execute)'); } + /** + * Install an engine-wide {@link HookMetricsRecorder} that folds every + * hook's execution time into the request-scoped `Server-Timing` collector + * (the `hooks;dur=…;desc="N hooks"` span). This is the framework's ONLY + * caller of `setHookMetricsRecorder`, so it owns the engine's recorder; + * objectql stays observability-free (the lean `core` tier, ADR-0076) — the + * timing lives here in the runtime, which already depends on it. + * + * `countServerTiming` is a no-op unless a request opened a perf collector + * (perf-tuning mode), so this costs nothing when the feature is off. It + * composes with any recorder a host wired earlier (chains to it), and is + * idempotent across the multiple AppPlugins a multi-app env installs. + */ + private installHookMetricsTiming(ctx: PluginContext): void { + let ql: any; + try { + ql = ctx.getService('objectql'); + } catch { + return; // no engine on this kernel — nothing to wire + } + if (!ql || typeof ql.setHookMetricsRecorder !== 'function') return; + const existing = typeof ql.getHookMetricsRecorder === 'function' + ? ql.getHookMetricsRecorder() + : undefined; + if (existing?.__perfTimingFeed) return; // already installed by a sibling AppPlugin + ql.setHookMetricsRecorder({ + __perfTimingFeed: true, + recordExecution(label: any, outcome: any, durationMs: number) { + try { existing?.recordExecution?.(label, outcome, durationMs); } catch { /* keep timing isolated */ } + countServerTiming('hooks', durationMs, 'hooks'); + }, + recordSkip(label: any, reason: any) { + try { existing?.recordSkip?.(label, reason); } catch { /* noop */ } + }, + recordRetry(label: any, attempt: number) { + try { existing?.recordRetry?.(label, attempt); } catch { /* noop */ } + }, + }); + ctx.logger.debug('[AppPlugin] Installed hook-metrics Server-Timing feed'); + } + start = async (ctx: PluginContext) => { if (this.empty) { ctx.logger.debug('[AppPlugin] empty env — no app payload, skipping start', { diff --git a/packages/runtime/src/http-dispatcher.ts b/packages/runtime/src/http-dispatcher.ts index 8d0ae0ed0e..98417454f1 100644 --- a/packages/runtime/src/http-dispatcher.ts +++ b/packages/runtime/src/http-dispatcher.ts @@ -5,6 +5,7 @@ import { shouldDenyAnonymous, ANONYMOUS_DENY_STATUS, ANONYMOUS_DENY_CODE, ANONYMOUS_DENY_MESSAGE, } from '@objectstack/core'; import { isMcpServerEnabled } from '@objectstack/types'; +import { measureServerTiming } from '@objectstack/observability'; import { CoreServiceName } from '@objectstack/spec/system'; import { readServiceSelfInfo } from '@objectstack/spec/api'; import { MCP_OAUTH_SCOPES } from '@objectstack/spec/ai'; @@ -223,6 +224,18 @@ export class HttpDispatcher { return undefined; } + /** + * Resolve the per-request identity/session, timed as the `auth` + * `Server-Timing` span — the prime suspect for unexplained data-API + * overhead (session lookup, org-scope resolution). A no-op wrapper when + * perf-tuning is off, so it costs nothing on the normal path. + */ + private timedResolveExecutionContext( + opts: Parameters[0], + ): Promise { + return measureServerTiming('auth', () => resolveExecutionContext(opts), 'Identity/session'); + } + private success(data: any, meta?: any) { return { status: 200, @@ -1776,7 +1789,7 @@ export class HttpDispatcher { context: HttpProtocolContext, ): Promise { try { - return await resolveExecutionContext({ + return await this.timedResolveExecutionContext({ getService: (n: string) => this.resolveService(n, context.environmentId), getQl: async () => { const k: any = this.kernel; @@ -4299,7 +4312,7 @@ export class HttpDispatcher { // Resolve once per request; SecurityPlugin middleware reads // ctx.userId/roles/permissions/tenantId via opCtx.context. try { - context.executionContext = await resolveExecutionContext({ + context.executionContext = await this.timedResolveExecutionContext({ getService: (n: string) => this.resolveService(n, context.environmentId), // Resolve ObjectQL from the per-request kernel DIRECTLY. The scoped // `resolveService('objectql', envId)` factory can return a different diff --git a/packages/runtime/src/server-timing.integration.test.ts b/packages/runtime/src/server-timing.integration.test.ts new file mode 100644 index 0000000000..d2e3c8e85c --- /dev/null +++ b/packages/runtime/src/server-timing.integration.test.ts @@ -0,0 +1,78 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { LiteKernel } from '@objectstack/core'; +import { HonoServerPlugin } from '@objectstack/plugin-hono-server'; +import { SqlDriver } from '@objectstack/driver-sql'; + +/** + * End-to-end regression for the Server-Timing `db` span (issue #2408). + * + * Boots a REAL HTTP server (Hono, perf-tuning on), opens a socket, and hits a + * route whose handler runs real SQL through the driver. This is the one thing + * no single-layer unit test can show: the request-scoped collector that the + * Hono middleware opens with `AsyncLocalStorage` actually reaches the SQL + * driver's knex query listener across a genuine HTTP request, so the response's + * `Server-Timing` header reports the request's query count. + */ +describe('Server-Timing db span over a real HTTP server (integration)', () => { + let kernel: LiteKernel; + let driver: SqlDriver; + let baseUrl: string; + + beforeAll(async () => { + driver = new SqlDriver({ + client: 'better-sqlite3', + connection: { filename: ':memory:' }, + useNullAsDefault: true, + }); + const knexInstance = (driver as any).knex; + await knexInstance.schema.createTable('widgets', (t: any) => { + t.string('id').primary(); + t.string('name'); + }); + await knexInstance('widgets').insert([ + { id: '1', name: 'a' }, + { id: '2', name: 'b' }, + ]); + + kernel = new LiteKernel(); + kernel.use(new HonoServerPlugin({ port: 0, serverTiming: true, cors: false })); + await kernel.bootstrap(); + + const httpServer = kernel.getService('http.server'); + // A route whose handler runs two real queries through the driver — the + // same shape as a data-API list that does a find + a follow-up lookup. + httpServer.get('/widgets', async (_req: any, res: any) => { + const all = await driver.find('widgets', {}); + const one = await driver.find('widgets', { where: { id: '1' } }); + res.json({ all: all.length, one: one.length }); + }); + baseUrl = `http://127.0.0.1:${httpServer.getPort()}`; + }, 30_000); + + afterAll(async () => { + try { await (driver as any).knex?.destroy(); } catch { /* noop */ } + if (kernel) { + await Promise.race([ + kernel.shutdown(), + new Promise((resolve) => setTimeout(resolve, 10_000)), + ]); + } + }); + + it('reports the request\'s query count in the Server-Timing header', async () => { + const res = await fetch(`${baseUrl}/widgets`); + expect(res.status).toBe(200); + expect(await res.json()).toEqual({ all: 2, one: 1 }); + + const header = res.headers.get('Server-Timing'); + expect(header).toBeTruthy(); + expect(header).toMatch(/(^|, )total;dur=/); + expect(header).toContain('serialize;dur='); + // Two driver.find() calls → ≥2 SQL queries folded into ONE db span. + const m = header!.match(/db;dur=[\d.]+;desc="(\d+) queries"/); + expect(m, `expected a db span in: ${header}`).toBeTruthy(); + expect(Number(m![1])).toBeGreaterThanOrEqual(2); + }); +}); diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 0f41c51876..02ce513540 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -1093,6 +1093,9 @@ importers: '@objectstack/core': specifier: workspace:* version: link:../../core + '@objectstack/observability': + specifier: workspace:* + version: link:../../observability '@objectstack/spec': specifier: workspace:* version: link:../../spec