Skip to content

Commit dc2990f

Browse files
os-zhuangclaude
andauthored
feat(observability): per-request performance timing → Server-Timing (perf-tuning mode) (#2411)
* feat(observability): per-request performance timing → Server-Timing (perf-tuning mode) Surface per-request server-side timing to clients via the W3C `Server-Timing` response header so a slow request's phase breakdown shows up directly in the browser DevTools Network → Timing panel. `@objectstack/observability`: - New `PerfTiming` collector — a tiny, dependency-free per-request accumulator of named phase durations, plus an `AsyncLocalStorage`-backed ambient API (`runWithPerfTiming` / `currentPerfTiming`, and the no-op-when-disabled free functions `measureServerTiming` / `startServerTiming` / `recordServerTiming`) so any code on the request's async chain can record a phase without threading a request object through every layer. - `formatServerTiming` serializes marks to the spec grammar, coercing names to tokens and stripping quotes/backslashes/control chars from descriptions to prevent header injection. `@objectstack/plugin-hono-server`: - Opt-in middleware (registered before CORS) brackets the whole request as `total` and establishes the ambient collector; the HTTP adapter contributes `parse` (body parse) and `handler` (route handler) sub-phases. - Off by default — the header is a backend-fingerprinting surface. Enable with `new HonoServerPlugin({ serverTiming: true })` or `OS_SERVER_TIMING=true` (works through the default `os serve`). Disabled = zero-overhead no-ops. Docs: new "Server-Timing (perf-tuning mode)" section in docs/OBSERVABILITY.md. Tests: 17 unit (collector/serializer/ambient) + 4 adapter integration (header present when enabled with total+handler, absent by default, env toggle, explicit-false override). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> * fix(observability): linear underscore-trim in sanitizeName (CodeQL js/polynomial-redos) The `/^_+|_+$/g` regex backtracks polynomially on underscore-heavy input; since formatServerTiming is a public export the name is uncontrolled. Replace the trim with a linear charCode scan. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> --------- Co-authored-by: Jack Zhuang <277994282+os-zhuang@users.noreply.github.com> Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
1 parent 9ccfcd6 commit dc2990f

11 files changed

Lines changed: 558 additions & 0 deletions

File tree

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
---
2+
'@objectstack/observability': minor
3+
'@objectstack/plugin-hono-server': minor
4+
---
5+
6+
Observability: per-request performance timing surfaced via the `Server-Timing` response header ("perf-tuning mode").
7+
8+
`@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).
9+
10+
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

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -220,6 +220,58 @@ runtime: the OTel API surface is large and host-specific (Node vs. edge vs.
220220
browser), so we publish the parsing primitive and leave SDK wiring to the
221221
host.
222222

223+
## Server-Timing (perf-tuning mode)
224+
225+
Per-request server-side timing can be surfaced to clients via the W3C
226+
[`Server-Timing`](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing)
227+
response header. The browser DevTools **Network → Timing** panel renders these
228+
phases inline, which makes it trivial to see where wall-clock time went on a
229+
slow request without attaching a profiler.
230+
231+
```
232+
Server-Timing: total;dur=18.7;desc="Total server time", parse;dur=0.4;desc="Body parse", handler;dur=17.9;desc="Route handler"
233+
```
234+
235+
This is **off by default**: the header discloses internal phase durations,
236+
which is helpful for profiling but also lets a caller fingerprint the backend.
237+
Treat it as a perf-tuning toggle you flip in staging (or briefly in production
238+
behind an allowlist), not a default-on header.
239+
240+
Enable it on the Hono server plugin:
241+
242+
```ts
243+
new HonoServerPlugin({ serverTiming: true });
244+
```
245+
246+
…or, for the default `os serve` server (which constructs the plugin for you),
247+
via the environment:
248+
249+
```bash
250+
OS_SERVER_TIMING=true os serve
251+
```
252+
253+
When enabled, every response carries `total` (the whole request, measured by
254+
an outer middleware) plus any sub-phases the request recorded. The HTTP adapter
255+
contributes `parse` (request-body parsing) and `handler` (route-handler
256+
execution) out of the box.
257+
258+
### Recording your own phases
259+
260+
Timing is collected through a request-scoped `AsyncLocalStorage` collector, so
261+
any code on the request's async call chain can add a phase without threading a
262+
request object through every layer. The free functions are cheap no-ops when
263+
the feature is off, so they are safe to leave in place permanently:
264+
265+
```ts
266+
import { measureServerTiming } from '@objectstack/observability';
267+
268+
const rows = await measureServerTiming('db', () => engine.find(query), 'Primary query');
269+
// → adds `db;dur=<ms>;desc="Primary query"` to the response when perf-tuning is on.
270+
```
271+
272+
`startServerTiming(name)` (returns an `end()` callback) and
273+
`recordServerTiming(name, dur)` are also available for manual instrumentation.
274+
223275
## Go-live checklist
224276

225277
- [ ] `metrics` adapter configured and `/metrics` (Prometheus) or OTel
@@ -234,3 +286,5 @@ host.
234286
- [ ] Log records include `requestId` field; cross-checked one against the
235287
response `X-Request-Id` header.
236288
- [ ] Alerts wired: error rate, p95 latency per route.
289+
- [ ] (Optional) `Server-Timing` verified in DevTools when `serverTiming` /
290+
`OS_SERVER_TIMING=true` is enabled, and confirmed **absent** by default.

packages/observability/src/index.ts

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,3 +40,16 @@ export {
4040
LOG_LEVELS,
4141
type LogLevel,
4242
} from './loggers.js';
43+
44+
// Per-request performance timing (Server-Timing header)
45+
export {
46+
PerfTiming,
47+
perfNow,
48+
formatServerTiming,
49+
runWithPerfTiming,
50+
currentPerfTiming,
51+
recordServerTiming,
52+
startServerTiming,
53+
measureServerTiming,
54+
type ServerTimingMark,
55+
} from './perf-timing.js';
Lines changed: 142 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,142 @@
1+
// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
import { describe, it, expect } from 'vitest';
4+
import {
5+
PerfTiming,
6+
formatServerTiming,
7+
runWithPerfTiming,
8+
currentPerfTiming,
9+
recordServerTiming,
10+
startServerTiming,
11+
measureServerTiming,
12+
} from './perf-timing.js';
13+
14+
describe('formatServerTiming', () => {
15+
it('serializes name + duration', () => {
16+
expect(formatServerTiming([{ name: 'db', dur: 12.3 }])).toBe('db;dur=12.3');
17+
});
18+
19+
it('rounds duration to 2 decimals', () => {
20+
expect(formatServerTiming([{ name: 'db', dur: 12.34567 }])).toBe('db;dur=12.35');
21+
});
22+
23+
it('emits a quoted desc when present', () => {
24+
expect(formatServerTiming([{ name: 'total', dur: 5, desc: 'Total time' }])).toBe(
25+
'total;dur=5;desc="Total time"',
26+
);
27+
});
28+
29+
it('joins multiple marks with comma-space', () => {
30+
expect(
31+
formatServerTiming([
32+
{ name: 'parse', dur: 1 },
33+
{ name: 'handler', dur: 4 },
34+
]),
35+
).toBe('parse;dur=1, handler;dur=4');
36+
});
37+
38+
it('sanitizes names into tokens', () => {
39+
expect(formatServerTiming([{ name: 'db query!', dur: 1 }])).toBe('db_query;dur=1');
40+
});
41+
42+
it('drops marks whose name is empty after sanitization', () => {
43+
expect(formatServerTiming([{ name: '!!!', dur: 1 }])).toBe('');
44+
});
45+
46+
it('strips quotes/backslashes/control chars from desc (no header injection)', () => {
47+
const out = formatServerTiming([
48+
{ name: 'x', dur: 1, desc: 'a"b\\c\r\nInjected: 1' },
49+
]);
50+
expect(out).toBe('x;dur=1;desc="a b c Injected: 1"');
51+
expect(out).not.toContain('\n');
52+
expect(out).not.toContain('"a"b"');
53+
});
54+
55+
it('coerces non-finite durations to 0', () => {
56+
expect(formatServerTiming([{ name: 'x', dur: Number.NaN }])).toBe('x;dur=0');
57+
expect(formatServerTiming([{ name: 'x', dur: Number.POSITIVE_INFINITY }])).toBe('x;dur=0');
58+
});
59+
60+
it('returns empty string for no marks', () => {
61+
expect(formatServerTiming([])).toBe('');
62+
});
63+
});
64+
65+
describe('PerfTiming', () => {
66+
it('records explicit marks in order', () => {
67+
const t = new PerfTiming();
68+
t.record('a', 1);
69+
t.record('b', 2);
70+
expect(t.marks().map((m) => m.name)).toEqual(['a', 'b']);
71+
expect(t.toHeader()).toBe('a;dur=1, b;dur=2');
72+
});
73+
74+
it('start() returns an idempotent end()', () => {
75+
const t = new PerfTiming();
76+
const end = t.start('phase');
77+
end();
78+
end(); // second call ignored
79+
expect(t.marks()).toHaveLength(1);
80+
expect(t.marks()[0].name).toBe('phase');
81+
expect(t.marks()[0].dur).toBeGreaterThanOrEqual(0);
82+
});
83+
84+
it('measure() records duration and returns the value', async () => {
85+
const t = new PerfTiming();
86+
const value = await t.measure('work', async () => {
87+
await new Promise((r) => setTimeout(r, 5));
88+
return 42;
89+
});
90+
expect(value).toBe(42);
91+
expect(t.marks()).toHaveLength(1);
92+
expect(t.marks()[0].dur).toBeGreaterThan(0);
93+
});
94+
95+
it('measure() records even when the function throws', async () => {
96+
const t = new PerfTiming();
97+
await expect(
98+
t.measure('boom', async () => {
99+
throw new Error('nope');
100+
}),
101+
).rejects.toThrow('nope');
102+
expect(t.marks()).toHaveLength(1);
103+
expect(t.marks()[0].name).toBe('boom');
104+
});
105+
});
106+
107+
describe('ambient collector', () => {
108+
it('currentPerfTiming() is undefined outside a run scope', () => {
109+
expect(currentPerfTiming()).toBeUndefined();
110+
});
111+
112+
it('free functions are no-ops with no active collector', async () => {
113+
recordServerTiming('x', 1); // must not throw
114+
const end = startServerTiming('y');
115+
end(); // must not throw
116+
const v = await measureServerTiming('z', async () => 7);
117+
expect(v).toBe(7);
118+
});
119+
120+
it('records onto the ambient collector inside runWithPerfTiming', async () => {
121+
const t = new PerfTiming();
122+
await runWithPerfTiming(t, async () => {
123+
expect(currentPerfTiming()).toBe(t);
124+
recordServerTiming('db', 3, 'Database');
125+
const v = await measureServerTiming('compute', async () => 'ok');
126+
expect(v).toBe('ok');
127+
});
128+
const names = t.marks().map((m) => m.name);
129+
expect(names).toContain('db');
130+
expect(names).toContain('compute');
131+
expect(t.toHeader()).toContain('db;dur=3;desc="Database"');
132+
});
133+
134+
it('propagates across async boundaries', async () => {
135+
const t = new PerfTiming();
136+
await runWithPerfTiming(t, async () => {
137+
await new Promise((r) => setTimeout(r, 1));
138+
recordServerTiming('after-await', 1);
139+
});
140+
expect(t.marks().map((m) => m.name)).toContain('after-await');
141+
});
142+
});

0 commit comments

Comments
 (0)