feat(observability): admin-only per-request timing detail via X-OS-Debug-Timing: json (#2408)

.changeset/perf-timing-admin-detail.md

@@ -0,0 +1,29 @@
+---
+"@objectstack/observability": minor
+"@objectstack/plugin-hono-server": minor
+"@objectstack/driver-sql": minor
+---
+
+feat(observability): admin-only richer per-request timing detail via `X-OS-Debug-Timing: json` (#2408)
+
+Completes the optional "richer JSON" diagnostic from #2408. In addition to the
+basic `Server-Timing` header, an admin/service caller can now request a
+per-query breakdown — the slowest SQL statements and a query count — by sending
+`X-OS-Debug-Timing: json`. The detail is returned in a separate
+`X-OS-Debug-Timing-Detail` response header (compact JSON) and is **admin-only,
+even under global mode**: an ordinary caller never sees SQL shapes.
+
+- **observability**: `PerfTiming` gains opt-in per-event detail capture
+  (`enableDetail` / `recordDetail` / `details`) plus the ambient
+  `recordServerTimingDetail`. The disclosure gate gains a `privileged` level
+  (set by `allowPerfDisclosure`, read via `isPerfDisclosurePrivileged`) so the
+  richer detail can be gated independently of the basic header.
+- **driver-sql**: when detail capture is on, the query listener additionally
+  records each query's **parametrized** statement (knex's `q.sql`, `?`
+  placeholders) — never the bindings, so no literal row value ever enters the
+  collector. Zero overhead when detail is off.
+- **plugin-hono-server**: `X-OS-Debug-Timing: json` enables detail capture; the
+  middleware emits `X-OS-Debug-Timing-Detail` (slowest queries, capped and
+  sanitized to header-safe ASCII) only when the principal is a proven admin.
+
+Basic and global behavior are unchanged; `json` is purely additive.

docs/OBSERVABILITY.md

@@ -271,6 +271,28 @@ they can never pull timings, so this is safe to leave available on a live
 environment. This is the path to reach for when diagnosing "why is *this* request
 slow?" against a running environment.
 
+For a per-query breakdown, an admin sends `json` instead:
+
+```
+X-OS-Debug-Timing: json
+```
+
+which adds an **admin-only** `X-OS-Debug-Timing-Detail` response header — compact
+JSON listing the slowest SQL statements (by shape), the single slowest, and the
+query count:
+
+```json
+{"db":{"count":6,"totalMs":210.3,"slowest":{"sql":"select * from widgets where id = ?","dur":88.1},"queries":[{"sql":"select * from widgets where id = ?","dur":88.1}, …]}}
+```
+
+The statements are **parametrized** — knex's `?` placeholders, never the
+bindings — so the query *shape* (the useful part for spotting N round-trips) is
+exposed while literal row values never leave the server. The detail is
+**admin-only even under global mode**: an ordinary caller who sends `json` still
+gets the basic `Server-Timing` header (if global mode is on) but never the
+`X-OS-Debug-Timing-Detail` payload. The list is capped and the labels sanitized
+to header-safe ASCII.
+
 To hard-disable both paths (no middleware registered at all), set
 `serverTiming: false` explicitly.
 
@@ -285,7 +307,7 @@ out of the box:
 | `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. |
+| `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). The basic header carries no SQL text; individual **parametrized** statements appear only in the admin-only `X-OS-Debug-Timing: json` detail payload. |
 | `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
@@ -336,5 +358,7 @@ countServerTiming('db', queryMs, 'queries'); // → db;dur=<sum>;desc="<n> queri
 - [ ] Alerts wired: error rate, p95 latency per route.
 - [ ] (Optional) `Server-Timing` verified in DevTools with global mode
       (`serverTiming: true` / `OS_PERF_TIMING=1`) on, confirmed **absent** for a
-      normal request, and confirmed the per-request `X-OS-Debug-Timing: 1` header
-      returns timing **only** to an admin/service caller.
+      normal request, confirmed the per-request `X-OS-Debug-Timing: 1` header
+      returns timing **only** to an admin/service caller, and confirmed
+      `X-OS-Debug-Timing: json` returns the `X-OS-Debug-Timing-Detail` payload
+      **only** to an admin (never to an ordinary caller, even under global mode).

packages/observability/src/index.ts

@@ -52,9 +52,12 @@ export {
     startServerTiming,
     measureServerTiming,
     countServerTiming,
+    recordServerTimingDetail,
     runWithPerfDisclosure,
     allowPerfDisclosure,
     isPerfDisclosureAllowed,
+    isPerfDisclosurePrivileged,
     type ServerTimingMark,
+    type ServerTimingDetail,
     type PerfDisclosureGate,
 } from './perf-timing.js';

packages/observability/src/perf-timing.test.ts

@@ -13,6 +13,8 @@ import {
     runWithPerfDisclosure,
     allowPerfDisclosure,
     isPerfDisclosureAllowed,
+    isPerfDisclosurePrivileged,
+    recordServerTimingDetail,
     type PerfDisclosureGate,
 } from './perf-timing.js';
 
@@ -213,11 +215,88 @@ describe('ambient collector', () => {
     });
 });
 
+describe('detail capture', () => {
+    it('is off by default — recordDetail is a no-op, details() empty', () => {
+        const t = new PerfTiming();
+        expect(t.detailEnabled).toBe(false);
+        t.recordDetail('db', 'select * from x where id = ?', 5);
+        expect(t.details('db')).toEqual([]);
+    });
+
+    it('captures per-event samples once enabled', () => {
+        const t = new PerfTiming();
+        t.enableDetail();
+        t.recordDetail('db', 'select a from t', 3);
+        t.recordDetail('db', 'select b from t where id = ?', 9);
+        const db = t.details('db');
+        expect(db).toHaveLength(2);
+        expect(db[1]).toEqual({ label: 'select b from t where id = ?', dur: 9 });
+    });
+
+    it('keeps categories separate and coerces bad durations to 0', () => {
+        const t = new PerfTiming();
+        t.enableDetail();
+        t.recordDetail('db', 'q', Number.NaN);
+        t.recordDetail('hooks', 'h', -4);
+        expect(t.details('db')).toEqual([{ label: 'q', dur: 0 }]);
+        expect(t.details('hooks')).toEqual([{ label: 'h', dur: 0 }]);
+    });
+
+    it('bounds retained samples at the cap', () => {
+        const t = new PerfTiming();
+        t.enableDetail();
+        for (let i = 0; i < 1200; i++) t.recordDetail('db', `q${i}`, 1);
+        expect(t.details('db').length).toBe(1000);
+    });
+
+    it('recordServerTimingDetail folds onto the ambient collector only when enabled', async () => {
+        const off = new PerfTiming();
+        await runWithPerfTiming(off, async () => {
+            recordServerTimingDetail('db', 'select 1', 2); // detail off → dropped
+        });
+        expect(off.details('db')).toEqual([]);
+
+        const on = new PerfTiming();
+        on.enableDetail();
+        await runWithPerfTiming(on, async () => {
+            recordServerTimingDetail('db', 'select 1 where id = ?', 2);
+        });
+        expect(on.details('db')).toEqual([{ label: 'select 1 where id = ?', dur: 2 }]);
+    });
+
+    it('recordServerTimingDetail is a no-op with no active collector', () => {
+        recordServerTimingDetail('db', 'select 1', 1); // must not throw
+    });
+});
+
 describe('disclosure gate', () => {
     it('isPerfDisclosureAllowed() is false with no active gate', () => {
         expect(isPerfDisclosureAllowed()).toBe(false);
     });
 
+    it('privileged is false with no active gate, and allowPerfDisclosure sets both', () => {
+        expect(isPerfDisclosurePrivileged()).toBe(false);
+        const gate: PerfDisclosureGate = { allowed: false };
+        runWithPerfDisclosure(gate, () => {
+            expect(isPerfDisclosurePrivileged()).toBe(false);
+            allowPerfDisclosure();
+            expect(isPerfDisclosureAllowed()).toBe(true);
+            expect(isPerfDisclosurePrivileged()).toBe(true);
+        });
+        expect(gate.allowed).toBe(true);
+        expect(gate.privileged).toBe(true);
+    });
+
+    it('global-mode disclosure (allowed but not privileged) does not grant privilege', () => {
+        // The middleware seeds `{ allowed: true }` for global mode WITHOUT calling
+        // allowPerfDisclosure — so basic timing discloses but detail stays gated.
+        const gate: PerfDisclosureGate = { allowed: true };
+        runWithPerfDisclosure(gate, () => {
+            expect(isPerfDisclosureAllowed()).toBe(true);
+            expect(isPerfDisclosurePrivileged()).toBe(false);
+        });
+    });
+
     it('allowPerfDisclosure() is a no-op with no active gate (does not throw)', () => {
         allowPerfDisclosure();
         expect(isPerfDisclosureAllowed()).toBe(false);

packages/observability/src/perf-timing.ts

@@ -45,6 +45,21 @@ export interface ServerTimingMark {
     desc?: string;
 }
 
+/**
+ * One recorded sub-event when DETAIL capture is on (see
+ * {@link PerfTiming.enableDetail}). Unlike the aggregate `db` mark — which folds
+ * every query into a single count+duration — a detail sample keeps the
+ * individual event so an admin can see *which* queries ran and which was
+ * slowest. `label` is a description of the event (for SQL: the PARAMETRIZED
+ * statement, bindings stripped — the query shape, never literal row values).
+ */
+export interface ServerTimingDetail {
+    /** Event label — e.g. a parametrized SQL statement (no bindings). */
+    label: string;
+    /** Duration in milliseconds. */
+    dur: number;
+}
+
 /**
  * Monotonic millisecond clock. Prefers `performance.now()` (monotonic, not
  * affected by wall-clock adjustments); falls back to `Date.now()` on the rare
@@ -138,12 +153,64 @@ export class PerfTiming {
      * already inserted into {@link _marks}, mutated in place as events arrive.
      */
     private _aggregates?: Map<string, { mark: ServerTimingMark; count: number; unit?: string }>;
+    /**
+     * Per-event detail samples by category, populated only while detail capture
+     * is on (see {@link enableDetail}). Lazily created so a request that never
+     * enables detail pays nothing.
+     */
+    private _detail?: Map<string, ServerTimingDetail[]>;
+    private _detailOn = false;
+    /**
+     * Hard cap on stored detail samples per category — detail is only ever on
+     * for a deliberate debug request, but a pathological request must not pin
+     * unbounded memory. The aggregate {@link count} still reflects the true
+     * total; only the retained per-event list is bounded.
+     */
+    private static readonly DETAIL_CAP = 1000;
 
     /** Record an already-measured phase. */
     record(name: string, dur: number, desc?: string): void {
         this._marks.push({ name, dur, desc });
     }
 
+    /**
+     * Turn on per-event DETAIL capture for this request. Off by default so the
+     * hot path never allocates a per-event list; the HTTP middleware enables it
+     * only for an admin-gated `X-OS-Debug-Timing: json` request. Idempotent.
+     */
+    enableDetail(): void {
+        this._detailOn = true;
+    }
+
+    /** Whether per-event detail capture is on. */
+    get detailEnabled(): boolean {
+        return this._detailOn;
+    }
+
+    /**
+     * Record one per-event detail sample under `category` (e.g. `'db'`). A no-op
+     * unless {@link enableDetail} was called, so the hot-path call site (the SQL
+     * driver's query listener) pays only a boolean check when detail is off.
+     * Bounded by {@link DETAIL_CAP}; excess events still count toward the
+     * aggregate via {@link count} but are not retained individually.
+     */
+    recordDetail(category: string, label: string, dur: number): void {
+        if (!this._detailOn) return;
+        const detail = (this._detail ??= new Map());
+        let list = detail.get(category);
+        if (!list) {
+            list = [];
+            detail.set(category, list);
+        }
+        if (list.length >= PerfTiming.DETAIL_CAP) return;
+        list.push({ label: String(label), dur: Number.isFinite(dur) && dur > 0 ? dur : 0 });
+    }
+
+    /** Retained detail samples for `category`, in record order (empty when none). */
+    details(category: string): readonly ServerTimingDetail[] {
+        return this._detail?.get(category) ?? [];
+    }
+
     /**
      * Begin timing a phase. Returns an idempotent `end()` - the first call
      * records the elapsed duration; later calls are ignored, so it is safe to
@@ -284,6 +351,16 @@ export function countServerTiming(name: string, dur: number, unit?: string): voi
     store.getStore()?.count(name, dur, unit);
 }
 
+/**
+ * Record a per-event DETAIL sample (e.g. one parametrized SQL statement) onto
+ * the ambient collector — see {@link PerfTiming.recordDetail}. A no-op when no
+ * collector is active OR detail capture is off, so the hot-path call site pays
+ * only an `AsyncLocalStorage` lookup + a boolean check when not debugging.
+ */
+export function recordServerTimingDetail(category: string, label: string, dur: number): void {
+    store.getStore()?.recordDetail(category, label, dur);
+}
+
 // --- Disclosure gate (WHO may see the timing) -------------------------
 
 /**
@@ -302,10 +379,23 @@ export function countServerTiming(name: string, dur: number, unit?: string): voi
  *
  * Keeping this out of {@link PerfTiming} preserves the collector's invariant
  * ("it only measures, it never decides whether to emit").
+ *
+ * Two levels, because global mode discloses the basic header to everyone but the
+ * richer per-query detail must stay admin-only:
+ *  - `allowed`    — the basic `Server-Timing` header may be disclosed (opened by
+ *                   global mode for everyone, or by a proven admin per-request).
+ *  - `privileged` — the principal is a proven admin/service. Gates the richer,
+ *                   SQL-shape-bearing detail payload, which must NEVER reach an
+ *                   ordinary caller even when global mode is on.
  */
 export interface PerfDisclosureGate {
-    /** Whether the collected timing may be disclosed to the client. */
+    /** Whether the basic collected timing may be disclosed to the client. */
     allowed: boolean;
+    /**
+     * Whether the principal is a proven admin/service — gates the richer detail
+     * payload independently of `allowed`. Absent = not privileged.
+     */
+    privileged?: boolean;
 }
 
 /**
@@ -330,17 +420,30 @@ export function runWithPerfDisclosure<T>(gate: PerfDisclosureGate, fn: () => T):
 }
 
 /**
- * Open the ambient disclosure gate — the request has proven it may see its own
- * `Server-Timing` header (admin/service identity). A no-op when no gate is
- * active (perf-tuning off, or already-global mode with no gate to flip), so the
- * call site stays branch-free.
+ * Open the ambient disclosure gate — the request has proven an admin/service
+ * identity, so it may see its own `Server-Timing` header AND the richer detail
+ * payload. Sets both {@link PerfDisclosureGate.allowed} and `privileged`. A
+ * no-op when no gate is active (perf-tuning off), so the call site stays
+ * branch-free.
  */
 export function allowPerfDisclosure(): void {
     const g = gateStore.getStore();
-    if (g) g.allowed = true;
+    if (g) {
+        g.allowed = true;
+        g.privileged = true;
+    }
 }
 
 /** Whether the ambient disclosure gate is open. `false` when none is active. */
 export function isPerfDisclosureAllowed(): boolean {
     return gateStore.getStore()?.allowed ?? false;
 }
+
+/**
+ * Whether the ambient principal is a proven admin/service — gates the richer
+ * detail payload. `false` when no gate is active or only global-mode disclosure
+ * (not a proven admin) opened it.
+ */
+export function isPerfDisclosurePrivileged(): boolean {
+    return gateStore.getStore()?.privileged ?? false;
+}

packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts

@@ -100,4 +100,31 @@ describe('SqlDriver Server-Timing db span', () => {
         });
         expect(dbMark(t)?.desc).toBe('1 queries');
     });
+
+    describe('detail mode (admin-gated per-query SQL shapes)', () => {
+        it('records NO per-query detail when detail capture is off', async () => {
+            const t = new PerfTiming(); // detail not enabled
+            await runWithPerfTiming(t, async () => {
+                await knexInstance('orders').where({ status: 'open' }).select('*');
+            });
+            expect(dbMark(t)?.desc).toMatch(/^\d+ queries$/); // aggregate still recorded
+            expect(t.details('db')).toEqual([]); // …but no SQL shapes retained
+        });
+
+        it('records parametrized SQL (no bindings) when detail capture is on', async () => {
+            const t = new PerfTiming();
+            t.enableDetail();
+            await runWithPerfTiming(t, async () => {
+                await knexInstance('orders').where({ status: 'open' }).select('*');
+            });
+            const detail = t.details('db');
+            expect(detail.length).toBeGreaterThanOrEqual(1);
+            const sql = detail[0].label;
+            // Parametrized: carries a `?` placeholder, never the literal 'open'.
+            expect(sql).toContain('?');
+            expect(sql.toLowerCase()).toContain('select');
+            expect(sql).not.toContain('open');
+            expect(detail[0].dur).toBeGreaterThanOrEqual(0);
+        });
+    });
 });