Skip to content

Request lifecycle restructure and native tracing channels (#73) - #196

Open
okomarov wants to merge 4 commits into
mainfrom
refactor/73-request-lifecycle
Open

okomarov wants to merge 4 commits into
mainfrom
refactor/73-request-lifecycle

Conversation

@okomarov

@okomarov okomarov commented Oct 25, 2026 •

Copy link
Copy Markdown

Adds native tracing through Node's diagnostics_channel (#73). APM tools such as Sentry, Datadog and OpenTelemetry can subscribe for query, connection, transaction and pool-wait spans instead of rewriting the driver's source, as dd-trace and Sentry do today. Channel names and payloads follow the pg tracing-channel PR (brianc/node-postgres#3650), so one integration can serve both drivers. Nothing is published or allocated unless something subscribes.

Why two parts

A request could reach a connection along several paths, queries and leases took different ones, and it could settle from several places. Tracing hooks would have been spread across all of them, so:

  • Part 1 restructures the request lifecycle so each step happens in one place: one router, one hand-over, one point where a query starts, one settle. Behaviour is unchanged apart from the resolve/reject counts below.
  • Part 2 adds the channels, each hooked at one of those places.

How pool waits are traced

pg checks a client out of the pool for every pool.query(), so its pool span covers every wait. Postgres.js has no checkout for plain queries, and it pipelines: when every connection is busy, it can send a query to a connection that is still running another one. So a query can wait in three places: in the pool queue, while a new connection opens, or behind another query on a busy connection.

postgres:pool:connect covers all three in one span, from asking for a connection until the connection starts the query. At hand-over it records handoverTime, which a subscriber can use to split it:

  • Before it is the wait for a connection, OpenTelemetry's db.client.connection.wait_time. A connection opened for this query shows as a postgres:connect child span here.
  • After it is the time queued behind other queries on that connection. queuedBehind says how many were ahead.

Pool Wait Spans compares this with the two alternatives (#192's, and a span that ends at hand-over).

Part 2: tracing channels (9722b28)

Channel Kind Covers
postgres:query TracingChannel every query, call to settlement
postgres:pool:connect TracingChannel every wait for a connection, for queries and leases
postgres:connect TracingChannel each connection attempt, including TLS and authentication
postgres:transaction TracingChannel sql.begin() and sql.savepoint(), with result: { committed }
postgres:pool:release channel a lease returning its connection; error only if the connection was lost
postgres:pool:remove channel a connection closing

No payload carries parameter values. docs/lifecycle.md lists the hook sites and docs/api.md the payloads.

Part 1: request lifecycle (a6b5623, 1c3bc59, 2970909)

  • Every request, a Query or a lease, carries a stage (New, Queued, Opening, Sent, Active, Settled). step, succeed and fail in src/query.js are its only writers, and a request settles once.
  • route is the one router for queries and leases, and never settles. assign is the one hand-over. A lease waits in the queue itself, so the separate waiter object is gone.
  • The connection starts queries in one place, activate.
  • The code shapes dd-trace rewrites are unchanged. The Sentry-range tracing variant is removed, because Sentry's rewrite only applies below 4.x.

The one behaviour difference: resolve and reject now run once per query (twice for COPY). Only code that wraps them sees it.

Path main here
sql\begin`` on a pool (UNSAFE_TRANSACTION) 1 resolve, 1 reject 0, 1
cancelled before it is awaited, max: 1 3 rejects 1
cancelled in a reserved connection's queue 3 rejects 1
cancelled in a transaction's queue 3 rejects 1

Evidence

Does this PR cost CPU?

Question Who it affects Measured
Does the restructure (Part 1) cost CPU against main? everyone no measurable change (p = 0.20)
Does tracing cost CPU when nothing subscribes? everyone, since most users never trace no measurable change (p = 0.18 against Part 1, 0.31 against main)
How much does tracing cost when an APM tool subscribes? Sentry, Datadog and OTel users under 1 ms per request: percentiles unchanged, rank test p = 0.015
Comparison on Cloudflare Workers Run Median p95 p99 Costs more, p
Part 1 against main 40357338624 13 / 14 ms 20 / 20 ms 35 / 29 ms 0.20
Part 2 against Part 1, nothing subscribed 40360228129 20 / 21 ms 47 / 45 ms 54 / 50 ms 0.18
This branch against main, nothing subscribed 40357278590 11 / 11 ms 17 / 16 ms 29 / 23 ms 0.31
Every channel subscribed against nothing subscribed 40357291633 13 / 13 ms 19 / 19 ms 27 / 25 ms 0.015
  • Each run deploys both builds in one Worker and runs 150 shuffled rounds of each. A round connects through Hyperdrive with prepare: true and fetch_types, runs four parameterized queries, three of them at once, and ends. CPU is Workers Logs cpuTimeMs in whole milliseconds; the test is a one-sided Mann-Whitney.
  • The subscribed build binds an AsyncLocalStorage store to every tracing channel, as Sentry does, and subscribes no-op handlers to all six channels.
  • The Part 2 run landed in 39 fresh isolates, which is why its numbers are higher. Requests that were first in their isolate cost 44 / 45 ms at the median, and later ones 18 / 18 ms, so the tracing code adds no visible cold-start cost either.
  • Earlier runs with one unprepared select 1 per connection (40237682305, 40244172825, 40244200407, 40241580406) agree, but mostly measure connection setup. Per-query allocation is not measured.

npm run test:tracing shows dd-trace and Sentry behaving as on 3.4.9 on every commit, including COPY and a dd-trace run with every channel subscribed.

@okomarov
okomarov force-pushed the refactor/73-request-lifecycle branch 9 times, most recently from 1bd3af3 to df292b3 Compare October 25, 2026 21:48
…t settling before the restructure (#73)

The restructure of the pool and query side (#73) must not change behaviour, so
this commit adds what holds it to that. Everything here passes on main.

The tracing comparison against Postgres.js 3.4.9 (npm run test:tracing) was only
ever run by hand, although dd-trace and Sentry rewrite and wrap the driver by
shape. It is now a job on every pull request, and a release waits for it. The
harness gains COPY to stdout and from stdin, a query cancelled before it is sent
and a query that fails to build. dd-trace ends a COPY span on the second resolve
of the query, so a change that settles a query once would leave every COPY span
open and nothing noticed.

The guard tests assert what main does on real PostgreSQL, including paths that look
wrong. A spy counts resolve and reject calls in one table: COPY in and out resolve
twice, sql`begin` on a pool resolves after rejecting with UNSAFE_TRANSACTION, a
query cancelled before it is awaited rejects once at max: 2 and three times at
max: 1 (the refused statement is written and its reply trips BindComplete on the
unbuilt statement), and a query cancelled in the queue of a reserved connection or
of a transaction rejects three times. A query cancelled before it is awaited is
still routed: never built, the pool keeps working, an idle connection is filed busy
and a connection that was still closed opens idle. A reservation queued behind plain
queries gets the connection after them, close() during the first query's connection
start runs that query and lets the next one reopen, and two paths that stay raw are
pinned with a thrown string: a cursor callback that throws, and queries rejected
after a failed reconnect while the pool is ending.
… path (#73)

Native tracing channels need single places to hook: where a request starts,
where it is routed, where it gets a connection, where it becomes active and where
it settles. The pool and query side had none. A query was resolved or rejected
from some thirty places, several running twice for the same query, the routing
decision was written twice (handler and lease) with small differences, and the
connection placed a query in two places. This restructures that with no change in
what the driver does, except for the one difference below.

A request, a Query or a lease, carries a stage (New, Queued, Opening, Sent,
Active, Settled) and is moved by step, succeed and fail in query.js. A request
settles once: later calls do nothing. fail only settles; queryError still decorates
the error and wraps a thrown non-object exactly as on main, so errors the pool
raises or a cursor callback throws stay raw. The COPY hand-out stays a direct
resolve of the stream (deliver) because dd-trace ends a COPY span on the second
resolve. The four resolve and reject arrows are untouched.

handler and lease commit after route, which takes a connection, starts an
acquisition or queues the request and returns the connection, null or the refusal,
but never settles or executes anything. assign is the one place a pool request
gets a connection, for queries and leases alike. A lease is created first with the
request shape and is its own waiter in the pool queue, so the waiter object and its
closure are gone. The connection places queries in one activate function, and an
ending connection's opener now goes through onopen like every other opener, with
an explicit argument saying the connection is draining. The three function handler
declarations and the other shapes dd-trace rewrites are unchanged.

The one deliberate difference: resolve and reject run once per query (twice for
COPY) instead of twice on some paths. Only code that wraps them sees it. The
pinned counts that change:

- sql`begin` on a pool rejected with UNSAFE_TRANSACTION and then resolved: one
  resolve and one reject become one reject.
- A query cancelled before it is awaited at max: 1 rejected three times, from the
  cancel, from BindComplete reading the statement of a query that was never built
  and from ReadyForQuery. It rejects once.
- A query cancelled in the queue of a reserved connection rejects once instead of
  three times, and so does one cancelled in the queue of a transaction.

BindComplete now returns early for a query without a statement, which removes the
TypeError that went through protocolError for a refused statement.

The tracing comparison no longer runs the Sentry variant that widened Sentry's
postgres range. Sentry's range never covers 4.x, so that variant emulated a setup
no user has and made Sentry's wrapping of handle, Connection, execute and connect
look like constraints on this code. The sentry-auto and sentry-manual runs stay,
and dd-trace's range has no upper bound, so its runs and shape constraints are
unchanged.

The test checker follows the request stages: request edges, every routed request
and lease settling, one hand-over per request and fresh exactly for the opener.
New tests pin one call for describe, cursors, forEach, simple, unsafe and file
queries, pipelined, reserved and retried queries, build failures and a destroyed
pool, and the requests scenarios assert each route's stage sequence and hand-over.
…cycle (#73)

lifecycle.md gains a Requests section: the shape a query and a lease share, the
stages and their transitions, the contract that route never settles a request and
where aborts and timeouts of a waiting request belong, assign as the one
hand-over, early settle while a query still holds its slot, COPY resolving twice
through deliver, settled requests still being routed, and where errors are
wrapped. The pool callbacks table describes onopen's draining argument, Cancel is
described in stage terms, the Test hook section lists the routed, step,
requestSettled and handover reports, and the open questions record the quirks
that stay as they are. The diff since 3.4.9 is refreshed.
@okomarov
okomarov force-pushed the refactor/73-request-lifecycle branch 4 times, most recently from 9fc5d49 to bd4add0 Compare October 25, 2026 23:18
#73)

The driver now publishes diagnostics_channel events that APM tools can
subscribe to without patching it. Nothing is published, and nothing is
allocated, while a channel has no subscriber.

TracingChannels, each following tracePromise order (start, end, error,
asyncStart, asyncEnd) and settling once:

- postgres:query, one per query, started in Query.handle in the caller's
  async context so a bindStore transform sees it. The text and statement
  name are filled in when the query is built for a connection.
- postgres:connect, one per connection acquisition, from the socket
  attempt through the first ReadyForQuery.
- postgres:pool:connect, one per wait for a connection: every plain
  query inside its query span, and every sql.reserve() and sql.begin().
- postgres:transaction, for sql.begin() and sql.savepoint(), with
  result.committed once known.

Plain channels: postgres:pool:release when a reserved connection or
transaction lets go of its connection, and postgres:pool:remove when a
connection closes. Release carries an error only when the
connection is terminated instead of returned healthy.

The payload follows the field names of brianc/node-postgres#3650:
query { text, name } and client { database, host, port, user, ssl,
processID } on queries, connection {...} on connect, pool { totalCount,
idleCount, waitingCount, maxSize } then client { processID, reused } on
the pool span, and { client: { processID }, error } on release and
remove.

The pool span splits the wait. It starts when the request is routed.
assign() records handoverTime, the moment a connection took the request
over, and queuedBehind, how many queries that connection already had
running or waiting. A query's span ends when the connection makes it
its active query, so the time from handoverTime to the end is spent
behind those queries, and the time before it is the wait for a
connection. A request that never reached a connection (refused, cancelled in
the queue, connection attempt failed) fails the pool span first and
then itself. Once handed over, the pool span resolves, and a later
failure fails only the query span.

Not published: parameter values, in any payload; a send event; a
channel for LISTEN or subscriptions. Internal queries (type fetching,
session checks) are not traced.

Each hook sits on a single transition of the request lifecycle:
Query.handle, build, succeed/fail, assign, activate, the connection's
acquisition and close, and the lease release. Types, docs/api.md, a
workerd scenario, an A/B input for the Workers CPU job and
tests/tracing.js cover it.
@okomarov
okomarov force-pushed the refactor/73-request-lifecycle branch from bd4add0 to 9722b28 Compare October 25, 2026 23:31
@okomarov okomarov changed the title test: pin request routing and settling before the restructure (#73) Request lifecycle restructure and native tracing channels (#73) Oct 25, 2026
@okomarov
okomarov marked this pull request as ready for review October 27, 2026 11:20

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant