feat(observability): per-request Server-Timing — auth/db/hooks/serialize spans (perf-tuning mode)

.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.

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=<sum>;desc="<count> <unit>"` 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=<sum>;desc="<n> queries"
+```
 
 ## Go-live checklist
 

packages/observability/src/index.ts

@@ -51,5 +51,6 @@ export {
     recordServerTiming,
     startServerTiming,
     measureServerTiming,
+    countServerTiming,
     type ServerTimingMark,
 } from './perf-timing.js';

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<symbol, unknown>)[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 () => {

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<string, { mark: ServerTimingMark; count: number; unit?: string }>;
 
     /** 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=<sum>;desc="<count> <unit>"` (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<PerfTiming>();
+/**
+ * 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<symbol, AsyncLocalStorage<PerfTiming> | undefined>;
+const store: AsyncLocalStorage<PerfTiming> =
+    globalStore[STORE_KEY] ?? (globalStore[STORE_KEY] = new AsyncLocalStorage<PerfTiming>());
 
 /** Run `fn` with `timing` as the ambient collector for the async call chain. */
 export function runWithPerfTiming<T>(timing: PerfTiming, fn: () => T): T {
@@ -214,3 +273,13 @@ export async function measureServerTiming<T>(
     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);
+}

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",