feat(observability): per-request Server-Timing — auth/db/hooks/serialize spans (perf-tuning mode)#3107
Merged
Merged
Conversation
…lize spans (perf-tuning mode) Completes #2408. The opt-in Server-Timing header now breaks a request's server time into the phases that actually explain it, so an operator can read the breakdown in DevTools -> Network -> Timing without standing up an external tracing backend. - collector: PerfTiming.count() / countServerTiming() fold high-frequency events (per query, per hook) into one aggregate member (name;dur=<sum>;desc="<count> <unit>"). - db: SqlDriver wires knex query / query-response events (keyed by __knexQueryUid), attributing per-query time to the originating request via AsyncLocalStorage (correct under concurrency; SQL text is never emitted). - auth: the dispatcher times identity/session resolution. - hooks: fed through the engine's existing HookMetricsRecorder seam, wired from the runtime so objectql's lean core tier stays observability-free. - serialize: the HTTP adapter times response JSON encoding. Fix a latent dual-instance bug found by a real end-to-end HTTP test: the ambient AsyncLocalStorage store was a plain module-level const, so the ESM and CJS builds (or an inlined bundle) each got their own store. A request scope opened by the HTTP server was then invisible to the SQL driver / engine, silently dropping the cross-layer spans. The store is now pinned to a global-registry symbol so every copy shares one. Every span is a no-op when perf-tuning is off (serverTiming / OS_SERVER_TIMING), so there is zero measurable overhead on the normal path. Gating is unchanged (env flag / option); only durations and counts are exposed, never SQL text. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VoJNgMJRhgqm78xF7MxFhX
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
Contributor
📓 Docs Drift CheckThis PR changes 4 package(s): 19 hand-written doc(s) reference the affected code and may need an implementation-accuracy re-verification:
|
os-zhuang
marked this pull request as ready for review
July 17, 2026 12:26
This was referenced Jul 18, 2026
Merged
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Completes #2408.
What
Turns the opt-in
Server-Timingheader (perf-tuning mode) into a real per-request breakdown, so an operator can open DevTools → Network → Timing and see exactly where a request's server time went — no external tracing backend required.Before, only
total/parse/handlerwere emitted. A data request now also carries:authdbdescis the query count (db;dur=210;desc="6 queries")hooksserializeExample:
How
PerfTiming.count()/countServerTiming(name, dur, unit)fold high-frequency events into one aggregate member (name;dur=<sum>;desc="<count> <unit>"), so per-query / per-hook timing doesn't flood the header.SqlDriverwires knexquery/query-response/query-error(keyed by__knexQueryUid) and attributes each query to the originating request viaAsyncLocalStorage— correct under concurrency, never cross-attributing. SQL text is never emitted, only durations + a count.HookMetricsRecorderseam, wired from the runtime (AppPlugin) so@objectstack/objectql's leancoretier (ADR-0076) stays observability-free.c.json().Bug fix (surfaced by the end-to-end test)
The ambient
AsyncLocalStoragestore was a plain module-levelconst. Because@objectstack/observabilityships both an ESM and a CJS build (and may be inlined by a bundler), consumers could load separate copies, each with its own store — so a request scope opened by the HTTP server was invisible to the SQL driver / engine and the cross-layer spans silently never recorded. The store is now pinned to aSymbol.for(...)global-registry key so every copy shares one. A real-socket integration test now guards this.Gating / overhead
serverTiming: trueonHonoServerPluginorOS_SERVER_TIMING=true(satisfies the AC's "or env flag").AsyncLocalStoragelookup), so there is zero measurable overhead on the normal path.X-OS-Debug-Timingper-request path from the issue is intentionally out of scope — the env-flag gate already meets the acceptance criteria.Acceptance criteria
Server-Timingdecomposing total into ≥ auth, db (with query count), hooks, serializeTests
observability: 58 pass (collector aggregate, ambient scope, global-store invariant)driver-sql: 279 pass (incl. new db-span concurrency/attribution test)plugin-hono-server: 72 pass (incl. realserializespan + aggregate-through-header)runtime: app-plugin + dispatcher suites (284) pass; new real-HTTPserver-timing.integration.test.tsprovesdb;desc="N queries"end-to-end over a socketpnpm build: 71/71 green🤖 Generated with Claude Code
https://claude.ai/code/session_01VoJNgMJRhgqm78xF7MxFhX
Generated by Claude Code