feat(observability): per-request performance timing → Server-Timing (perf-tuning mode)

.changeset/server-timing-perf-tuning.md

@@ -0,0 +1,10 @@
+---
+'@objectstack/observability': minor
+'@objectstack/plugin-hono-server': minor
+---
+
+Observability: per-request performance timing surfaced via the `Server-Timing` response header ("perf-tuning mode").
+
+`@objectstack/observability` gains a tiny, dependency-free `PerfTiming` collector plus an `AsyncLocalStorage`-backed ambient API (`runWithPerfTiming` / `currentPerfTiming` and the no-op-when-disabled free functions `measureServerTiming` / `startServerTiming` / `recordServerTiming`) and a spec-compliant `formatServerTiming` serializer that sanitizes names to tokens and quotes/escapes descriptions (no header injection).
+
+The Hono server plugin can now emit `Server-Timing` per request. It is **off by default** — the header discloses internal phase durations, which is a backend-fingerprinting surface — and opt-in via `new HonoServerPlugin({ serverTiming: true })` or `OS_SERVER_TIMING=true` (so it works through the default `os serve`). When enabled, every response carries `total` (measured by an outer middleware that brackets the whole request) plus the adapter-contributed `parse` and `handler` sub-phases; any code on the request's async call chain can add its own phases via the ambient API. When disabled, the timing call sites are zero-overhead no-ops.

docs/OBSERVABILITY.md

@@ -220,6 +220,58 @@ runtime: the OTel API surface is large and host-specific (Node vs. edge vs.
 browser), so we publish the parsing primitive and leave SDK wiring to the
 host.
 
+## Server-Timing (perf-tuning mode)
+
+Per-request server-side timing can be surfaced to clients via the W3C
+[`Server-Timing`](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing)
+response header. The browser DevTools **Network → Timing** panel renders these
+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"
+```
+
+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
+behind an allowlist), not a default-on header.
+
+Enable it on the Hono server plugin:
+
+```ts
+new HonoServerPlugin({ serverTiming: true });
+```
+
+…or, for the default `os serve` server (which constructs the plugin for you),
+via the environment:
+
+```bash
+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.
+
+### Recording your own phases
+
+Timing is collected through a request-scoped `AsyncLocalStorage` collector, so
+any code on the request's async call chain can add a phase without threading a
+request object through every layer. The free functions are cheap no-ops when
+the feature is off, so they are safe to leave in place permanently:
+
+```ts
+import { measureServerTiming } from '@objectstack/observability';
+
+const rows = await measureServerTiming('db', () => engine.find(query), 'Primary query');
+// → adds `db;dur=<ms>;desc="Primary query"` to the response when perf-tuning is on.
+```
+
+`startServerTiming(name)` (returns an `end()` callback) and
+`recordServerTiming(name, dur)` are also available for manual instrumentation.
+
 ## Go-live checklist
 
 - [ ] `metrics` adapter configured and `/metrics` (Prometheus) or OTel
@@ -234,3 +286,5 @@ host.
 - [ ] Log records include `requestId` field; cross-checked one against the
       response `X-Request-Id` header.
 - [ ] Alerts wired: error rate, p95 latency per route.
+- [ ] (Optional) `Server-Timing` verified in DevTools when `serverTiming` /
+      `OS_SERVER_TIMING=true` is enabled, and confirmed **absent** by default.

packages/observability/src/index.ts

@@ -40,3 +40,16 @@ export {
     LOG_LEVELS,
     type LogLevel,
 } from './loggers.js';
+
+// Per-request performance timing (Server-Timing header)
+export {
+    PerfTiming,
+    perfNow,
+    formatServerTiming,
+    runWithPerfTiming,
+    currentPerfTiming,
+    recordServerTiming,
+    startServerTiming,
+    measureServerTiming,
+    type ServerTimingMark,
+} from './perf-timing.js';

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

@@ -0,0 +1,142 @@
+// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
+
+import { describe, it, expect } from 'vitest';
+import {
+    PerfTiming,
+    formatServerTiming,
+    runWithPerfTiming,
+    currentPerfTiming,
+    recordServerTiming,
+    startServerTiming,
+    measureServerTiming,
+} from './perf-timing.js';
+
+describe('formatServerTiming', () => {
+    it('serializes name + duration', () => {
+        expect(formatServerTiming([{ name: 'db', dur: 12.3 }])).toBe('db;dur=12.3');
+    });
+
+    it('rounds duration to 2 decimals', () => {
+        expect(formatServerTiming([{ name: 'db', dur: 12.34567 }])).toBe('db;dur=12.35');
+    });
+
+    it('emits a quoted desc when present', () => {
+        expect(formatServerTiming([{ name: 'total', dur: 5, desc: 'Total time' }])).toBe(
+            'total;dur=5;desc="Total time"',
+        );
+    });
+
+    it('joins multiple marks with comma-space', () => {
+        expect(
+            formatServerTiming([
+                { name: 'parse', dur: 1 },
+                { name: 'handler', dur: 4 },
+            ]),
+        ).toBe('parse;dur=1, handler;dur=4');
+    });
+
+    it('sanitizes names into tokens', () => {
+        expect(formatServerTiming([{ name: 'db query!', dur: 1 }])).toBe('db_query;dur=1');
+    });
+
+    it('drops marks whose name is empty after sanitization', () => {
+        expect(formatServerTiming([{ name: '!!!', dur: 1 }])).toBe('');
+    });
+
+    it('strips quotes/backslashes/control chars from desc (no header injection)', () => {
+        const out = formatServerTiming([
+            { name: 'x', dur: 1, desc: 'a"b\\c\r\nInjected: 1' },
+        ]);
+        expect(out).toBe('x;dur=1;desc="a b c Injected: 1"');
+        expect(out).not.toContain('\n');
+        expect(out).not.toContain('"a"b"');
+    });
+
+    it('coerces non-finite durations to 0', () => {
+        expect(formatServerTiming([{ name: 'x', dur: Number.NaN }])).toBe('x;dur=0');
+        expect(formatServerTiming([{ name: 'x', dur: Number.POSITIVE_INFINITY }])).toBe('x;dur=0');
+    });
+
+    it('returns empty string for no marks', () => {
+        expect(formatServerTiming([])).toBe('');
+    });
+});
+
+describe('PerfTiming', () => {
+    it('records explicit marks in order', () => {
+        const t = new PerfTiming();
+        t.record('a', 1);
+        t.record('b', 2);
+        expect(t.marks().map((m) => m.name)).toEqual(['a', 'b']);
+        expect(t.toHeader()).toBe('a;dur=1, b;dur=2');
+    });
+
+    it('start() returns an idempotent end()', () => {
+        const t = new PerfTiming();
+        const end = t.start('phase');
+        end();
+        end(); // second call ignored
+        expect(t.marks()).toHaveLength(1);
+        expect(t.marks()[0].name).toBe('phase');
+        expect(t.marks()[0].dur).toBeGreaterThanOrEqual(0);
+    });
+
+    it('measure() records duration and returns the value', async () => {
+        const t = new PerfTiming();
+        const value = await t.measure('work', async () => {
+            await new Promise((r) => setTimeout(r, 5));
+            return 42;
+        });
+        expect(value).toBe(42);
+        expect(t.marks()).toHaveLength(1);
+        expect(t.marks()[0].dur).toBeGreaterThan(0);
+    });
+
+    it('measure() records even when the function throws', async () => {
+        const t = new PerfTiming();
+        await expect(
+            t.measure('boom', async () => {
+                throw new Error('nope');
+            }),
+        ).rejects.toThrow('nope');
+        expect(t.marks()).toHaveLength(1);
+        expect(t.marks()[0].name).toBe('boom');
+    });
+});
+
+describe('ambient collector', () => {
+    it('currentPerfTiming() is undefined outside a run scope', () => {
+        expect(currentPerfTiming()).toBeUndefined();
+    });
+
+    it('free functions are no-ops with no active collector', async () => {
+        recordServerTiming('x', 1); // must not throw
+        const end = startServerTiming('y');
+        end(); // must not throw
+        const v = await measureServerTiming('z', async () => 7);
+        expect(v).toBe(7);
+    });
+
+    it('records onto the ambient collector inside runWithPerfTiming', async () => {
+        const t = new PerfTiming();
+        await runWithPerfTiming(t, async () => {
+            expect(currentPerfTiming()).toBe(t);
+            recordServerTiming('db', 3, 'Database');
+            const v = await measureServerTiming('compute', async () => 'ok');
+            expect(v).toBe('ok');
+        });
+        const names = t.marks().map((m) => m.name);
+        expect(names).toContain('db');
+        expect(names).toContain('compute');
+        expect(t.toHeader()).toContain('db;dur=3;desc="Database"');
+    });
+
+    it('propagates across async boundaries', async () => {
+        const t = new PerfTiming();
+        await runWithPerfTiming(t, async () => {
+            await new Promise((r) => setTimeout(r, 1));
+            recordServerTiming('after-await', 1);
+        });
+        expect(t.marks().map((m) => m.name)).toContain('after-await');
+    });
+});