|
| 1 | +--- |
| 2 | +title: Tracing with Diagnostics Channels |
| 3 | +sidebarTitle: Tracing Channels |
| 4 | +--- |
| 5 | + |
| 6 | +import { Callout } from 'nextra/components'; |
| 7 | + |
| 8 | +# Tracing with Diagnostics Channels |
| 9 | + |
| 10 | +<Callout type="info"> |
| 11 | + Tracing channels are available in GraphQL.js v17. They build on Node.js |
| 12 | + [`diagnostics_channel`](https://nodejs.org/api/diagnostics_channel.html) |
| 13 | + `TracingChannel` API. |
| 14 | +</Callout> |
| 15 | + |
| 16 | +GraphQL.js publishes lifecycle events on a set of named tracing channels that |
| 17 | +observability tools (APM agents, tracers, custom logging) can subscribe to in |
| 18 | +order to watch parsing, validation, variable coercion, execution, subscription |
| 19 | +setup, and individual resolver calls. |
| 20 | + |
| 21 | +Tracing is built on `node:diagnostics_channel`, so it is decoupled from the |
| 22 | +GraphQL.js API surface. You do not pass a tracer into `execute()` or wrap your |
| 23 | +schema. Instead, a subscriber attaches to a channel by name and GraphQL.js |
| 24 | +publishes to it whenever work happens. |
| 25 | + |
| 26 | +Typical uses include: |
| 27 | + |
| 28 | +- **Distributed tracing**: open a span per operation, root field, or resolver |
| 29 | + and export it to your APM or tracing backend. |
| 30 | +- **Performance monitoring**: time resolvers to surface slow fields and N+1 |
| 31 | + access patterns. |
| 32 | +- **Metrics**: count operations and record latency or error rates per |
| 33 | + operation, field, or stage. |
| 34 | +- **Error tracking**: capture parse, validation, coercion, and resolver errors |
| 35 | + along with their payloads. |
| 36 | +- **Structured logging and auditing**: log each operation with its outcome. |
| 37 | + |
| 38 | +## Subscribing to a Channel |
| 39 | + |
| 40 | +GraphQL.js resolves `node:diagnostics_channel` itself at module load and |
| 41 | +publishes automatically, so there is no tracer to install or schema to wrap. A |
| 42 | +subscriber just imports `node:diagnostics_channel` and attaches to a channel by |
| 43 | +name: |
| 44 | + |
| 45 | +```js |
| 46 | +import dc from 'node:diagnostics_channel'; |
| 47 | + |
| 48 | +const channel = dc.tracingChannel('graphql:execute'); |
| 49 | + |
| 50 | +channel.subscribe({ |
| 51 | + start(message) { |
| 52 | + // Runs when execution begins. |
| 53 | + }, |
| 54 | + end(message) { |
| 55 | + // Runs when the synchronous portion of execution finishes. |
| 56 | + }, |
| 57 | + asyncStart(message) { |
| 58 | + // Runs when an asynchronous execution continuation begins. |
| 59 | + }, |
| 60 | + asyncEnd(message) { |
| 61 | + // Runs when asynchronous execution settles. |
| 62 | + }, |
| 63 | + error(message) { |
| 64 | + // Runs when the traced call throws or rejects. `message.error` is the cause. |
| 65 | + }, |
| 66 | +}); |
| 67 | +``` |
| 68 | + |
| 69 | +On runtimes that do not expose `node:diagnostics_channel` (browsers, for |
| 70 | +example) the module load silently no-ops and every emission site |
| 71 | +short-circuits, so bundling GraphQL.js for the browser carries no tracing |
| 72 | +overhead and no error. |
| 73 | + |
| 74 | +## The Channels |
| 75 | + |
| 76 | +| Channel | Fires for | Context type | |
| 77 | +| --- | --- | --- | |
| 78 | +| `graphql:parse` | Each `parse()` call | [`GraphQLParseContext`](/api-v17/graphql#graphqlparsecontext) | |
| 79 | +| `graphql:validate` | Each `validate()` call | [`GraphQLValidateContext`](/api-v17/graphql#graphqlvalidatecontext) | |
| 80 | +| `graphql:execute` | Each `execute()` / `graphql()` operation | [`GraphQLExecuteContext`](/api-v17/graphql#graphqlexecutecontext) | |
| 81 | +| `graphql:execute:variableCoercion` | Variable coercion within an operation | [`GraphQLExecuteVariableCoercionContext`](/api-v17/graphql#graphqlexecutevariablecoercioncontext) | |
| 82 | +| `graphql:execute:rootSelectionSet` | Root selection set execution (also once per emitted subscription event) | [`GraphQLExecuteRootSelectionSetContext`](/api-v17/graphql#graphqlexecuterootselectionsetcontext) | |
| 83 | +| `graphql:subscribe` | Each `subscribe()` setup | [`GraphQLSubscribeContext`](/api-v17/graphql#graphqlsubscribecontext) | |
| 84 | +| `graphql:resolve` | Each field resolver invocation | [`GraphQLResolveContext`](/api-v17/graphql#graphqlresolvecontext) | |
| 85 | + |
| 86 | +<Callout type="warning"> |
| 87 | + `graphql:resolve` fires for every resolved field, including fields served by |
| 88 | + the default resolver, so a single response can produce a large number of |
| 89 | + events. There is no way to subscribe to a subset of fields, so keep the |
| 90 | + handlers cheap and do any heavy work off the hot path. |
| 91 | +</Callout> |
| 92 | + |
| 93 | +### Context Payloads |
| 94 | + |
| 95 | +Every context object receives its channel-specific fields at `start`. When the |
| 96 | +traced call completes normally, the terminal event receives a `result` |
| 97 | +property. When the traced call throws or rejects, the `error` sub-channel fires |
| 98 | +and the terminal event receives an `error` property. |
| 99 | + |
| 100 | +Here, "traced call" means the JavaScript unit wrapped by the channel, not |
| 101 | +necessarily a GraphQL operation. It may be a parser call, validation call, |
| 102 | +execution call, variable coercion step, subscription setup, root selection set, |
| 103 | +or individual resolver call. |
| 104 | + |
| 105 | +See the [Diagnostics |
| 106 | +reference](/api-v17/graphql#category-diagnostics) for the complete set of |
| 107 | +fields on each context type. The context types are also exported from the |
| 108 | +`graphql` package if you want to type message payloads in TypeScript. |
| 109 | + |
| 110 | +### GraphQL Errors and Tracing Errors |
| 111 | + |
| 112 | +The tracing `error` lifecycle event is not the same thing as a `GraphQLError` |
| 113 | +returned by GraphQL.js. It fires when the traced call throws or rejects. |
| 114 | +Several GraphQL.js channels can instead complete normally and put |
| 115 | +`GraphQLError` values in the context `result`: |
| 116 | + |
| 117 | +- `graphql:validate` returns its validation error array as `result`. |
| 118 | +- `graphql:execute`, `graphql:execute:rootSelectionSet`, and |
| 119 | + `graphql:subscribe` may return an `ExecutionResult` with `errors`. |
| 120 | +- `graphql:execute:variableCoercion` may return a coercion result with |
| 121 | + `errors`. |
| 122 | + |
| 123 | +A resolver error is the main wrinkle. If a resolver throws or rejects, the |
| 124 | +`graphql:resolve` event for that resolver emits the tracing `error` lifecycle |
| 125 | +event. Execution may still catch that resolver error, format it as a GraphQL |
| 126 | +field error, and include it in the result reported by `graphql:execute`, |
| 127 | +`graphql:execute:rootSelectionSet`, or a subscription response event. The same |
| 128 | +underlying resolver failure can therefore appear both as `message.error` on |
| 129 | +`graphql:resolve` and as a formatted GraphQL error in an enclosing result. |
| 130 | +Likewise, a subscription source resolver that throws or rejects is reported as |
| 131 | +an error result on `graphql:subscribe`, not as the `graphql:subscribe` tracing |
| 132 | +`error` lifecycle event. |
| 133 | + |
| 134 | +## The Lifecycle Events |
| 135 | + |
| 136 | +Each tracing channel exposes five sub-channels. GraphQL.js publishes them in a |
| 137 | +fixed order depending on whether the traced call is synchronous or returns a |
| 138 | +promise. |
| 139 | + |
| 140 | +- **Synchronous success:** `start` → `end` |
| 141 | +- **Synchronous failure:** `start` → `error` → `end` |
| 142 | +- **Asynchronous success:** `start` → `end` → `asyncStart` → `asyncEnd` |
| 143 | +- **Asynchronous failure:** `start` → `end` → `asyncStart` → `error` → `asyncEnd` |
| 144 | + |
| 145 | +`start` and `end` bracket the synchronous portion of the call. When the |
| 146 | +traced call continues asynchronously, `asyncStart` fires as the async |
| 147 | +continuation begins and `asyncEnd` fires once it settles. When the traced call |
| 148 | +throws or rejects, `error` fires before the terminal `end`/`asyncEnd` and |
| 149 | +carries the cause on `message.error`. |
| 150 | + |
| 151 | +GraphQL.js runs the traced work inside the `start` channel's `runStores`, so an |
| 152 | +`AsyncLocalStorage` bound to that channel with `channel.start.bindStore()` |
| 153 | +stays entered across the full async lifecycle. This is what lets a tracer open |
| 154 | +a span in `start` and close it in `asyncEnd`. |
| 155 | + |
| 156 | +<Callout type="info"> |
| 157 | + A subscriber that attaches partway through an in-flight operation will not |
| 158 | + see a matching `start`, and any `AsyncLocalStorage` context it expects will be |
| 159 | + missing. Attach subscribers before the operations you want to observe. |
| 160 | +</Callout> |
| 161 | + |
| 162 | +<Callout type="warning"> |
| 163 | + For incremental delivery (`@defer` and `@stream`), `graphql:execute` |
| 164 | + completes when the initial result is ready, not when the deferred and |
| 165 | + streamed payloads finish. Those later payloads are not `graphql:execute` |
| 166 | + events; the deferred fields still fire `graphql:resolve` as they execute. Do |
| 167 | + not treat the `graphql:execute` duration as the full request lifetime for |
| 168 | + incremental responses. |
| 169 | +</Callout> |
| 170 | + |
| 171 | +## How the Channels Fit Together |
| 172 | + |
| 173 | +A single request moves through the channels in a fixed order. `parse` and |
| 174 | +`validate` run first and independently, and they only fire if you call |
| 175 | +`parse()` and `validate()` (the `graphql()` harness does, but calling |
| 176 | +`execute()` with an already-parsed document fires only `execute` and below). |
| 177 | +Everything else nests inside `graphql:execute`. |
| 178 | + |
| 179 | +For this operation: |
| 180 | + |
| 181 | +```graphql |
| 182 | +query Q($id: ID!) { |
| 183 | + user(id: $id) { |
| 184 | + name |
| 185 | + posts { |
| 186 | + title |
| 187 | + } |
| 188 | + } |
| 189 | +} |
| 190 | +``` |
| 191 | + |
| 192 | +the channels fire like this, shown by their full lifecycle: |
| 193 | + |
| 194 | +```text |
| 195 | +graphql:parse parse the document |
| 196 | +graphql:validate validate against the schema |
| 197 | +graphql:execute the operation |
| 198 | +├─ graphql:execute:variableCoercion coerce $id |
| 199 | +└─ graphql:execute:rootSelectionSet execute the root selection set |
| 200 | + ├─ graphql:resolve user |
| 201 | + ├─ graphql:resolve user.name |
| 202 | + ├─ graphql:resolve user.posts |
| 203 | + ├─ graphql:resolve user.posts.0.title |
| 204 | + └─ graphql:resolve user.posts.1.title |
| 205 | +``` |
| 206 | + |
| 207 | +`variableCoercion` and `rootSelectionSet` nest inside `execute`, and a |
| 208 | +`graphql:resolve` event fires for every resolved field within |
| 209 | +`rootSelectionSet`. The resolve events are siblings, not nested in one another: |
| 210 | +`graphql:resolve` traces the resolver call itself, not the execution of that |
| 211 | +field's children. Reconstruct the field hierarchy from each event's |
| 212 | +`fieldPath`, shown above, not from channel nesting. |
| 213 | + |
| 214 | +Because each level follows the [lifecycle above](#the-lifecycle-events), the |
| 215 | +synchronous `end` of `execute` and `rootSelectionSet` fires before the |
| 216 | +resolvers settle; their full duration runs from `start` to `asyncEnd`. |
| 217 | + |
| 218 | +## Example: Timing Every Resolver |
| 219 | + |
| 220 | +```js |
| 221 | +import dc from 'node:diagnostics_channel'; |
| 222 | +import { AsyncLocalStorage } from 'node:async_hooks'; |
| 223 | + |
| 224 | +const store = new AsyncLocalStorage(); |
| 225 | +const channel = dc.tracingChannel('graphql:resolve'); |
| 226 | +const timings = []; |
| 227 | + |
| 228 | +// Scoped to a single resolver call: available in `end`/`asyncEnd`, cleaned up |
| 229 | +// afterward, and safe across concurrent resolvers. |
| 230 | +channel.start.bindStore(store, (message) => { |
| 231 | + const record = { |
| 232 | + field: `${message.parentType}.${message.fieldName}`, |
| 233 | + startedAt: performance.now(), |
| 234 | + }; |
| 235 | + timings.push(record); |
| 236 | + return record; |
| 237 | +}); |
| 238 | + |
| 239 | +channel.subscribe({ |
| 240 | + end(message) { |
| 241 | + // Fires for both synchronous and asynchronous resolvers. |
| 242 | + update(message.error); |
| 243 | + }, |
| 244 | + asyncEnd(message) { |
| 245 | + update(message.error); |
| 246 | + }, |
| 247 | +}); |
| 248 | + |
| 249 | +function update(error) { |
| 250 | + const record = store.getStore(); |
| 251 | + if (record === undefined) return; |
| 252 | + record.duration = performance.now() - record.startedAt; |
| 253 | + record.error = error; |
| 254 | +} |
| 255 | +``` |
| 256 | + |
| 257 | +Binding the store to `start` lets GraphQL.js scope the store to each resolver |
| 258 | +call and clean it up afterward. `end` fires for every resolver, while |
| 259 | +`asyncEnd` fires only for resolvers that return a promise, and always after |
| 260 | +`end`. Recording the duration in place (rather than pushing a new entry from |
| 261 | +each handler) is what keeps the asynchronous path from being counted twice. |
| 262 | + |
| 263 | +## Tracing Subscriptions |
| 264 | + |
| 265 | +`graphql:subscribe` wraps the subscription *setup*: building the event source |
| 266 | +from the subscription's root field. The result on success is the response |
| 267 | +stream. |
| 268 | + |
| 269 | +Each event that flows through the subscription is executed separately, so |
| 270 | +`graphql:execute:rootSelectionSet` fires once **per emitted event**. The two |
| 271 | +channels describe different units of work: |
| 272 | + |
| 273 | +- `graphql:subscribe` fires **once per subscription**. Subscribe to it to |
| 274 | + observe the subscription's lifetime and any failure setting it up. |
| 275 | +- `graphql:execute:rootSelectionSet` fires **once per delivered payload**. |
| 276 | + Subscribe to it to time and trace the execution of each individual event. |
| 277 | + |
| 278 | +```js |
| 279 | +import dc from 'node:diagnostics_channel'; |
| 280 | + |
| 281 | +// Subscription setup and overall lifetime. |
| 282 | +dc.tracingChannel('graphql:subscribe').subscribe({ |
| 283 | + start(message) { |
| 284 | + openSubscriptionSpan(message.operationName); |
| 285 | + }, |
| 286 | + end(message) { |
| 287 | + // Synchronous setup finished. `result` may be the response stream or an |
| 288 | + // ExecutionResult with setup errors. |
| 289 | + if ('result' in message) { |
| 290 | + closeSubscriptionSpan(message.result); |
| 291 | + } |
| 292 | + }, |
| 293 | + asyncEnd(message) { |
| 294 | + // Asynchronous setup finished. `result` may be the response stream or an |
| 295 | + // ExecutionResult with setup errors. |
| 296 | + if ('result' in message) { |
| 297 | + closeSubscriptionSpan(message.result); |
| 298 | + } |
| 299 | + }, |
| 300 | + error(message) { |
| 301 | + // The subscribe call failed abruptly, e.g. an unexpected runtime error. |
| 302 | + failSubscriptionSpan(message.error); |
| 303 | + }, |
| 304 | + // ... |
| 305 | +}); |
| 306 | + |
| 307 | +// Per-payload execution. `rootSelectionSet` also fires for queries and |
| 308 | +// mutations, so filter on the operation type. |
| 309 | +dc.tracingChannel('graphql:execute:rootSelectionSet').subscribe({ |
| 310 | + start(message) { |
| 311 | + if (message.operationType === 'subscription') { |
| 312 | + openEventSpan(message.operationName); |
| 313 | + } |
| 314 | + }, |
| 315 | + end(message) { |
| 316 | + if (message.operationType === 'subscription' && 'result' in message) { |
| 317 | + closeEventSpan(message.result); |
| 318 | + } |
| 319 | + }, |
| 320 | + asyncEnd(message) { |
| 321 | + if (message.operationType === 'subscription' && 'result' in message) { |
| 322 | + closeEventSpan(message.result); |
| 323 | + } |
| 324 | + }, |
| 325 | + // ... |
| 326 | +}); |
| 327 | +``` |
| 328 | + |
| 329 | +Listen to both when you want the subscribe event as the parent span and each |
| 330 | +delivered payload as a child; listen to just one when you only care about the |
| 331 | +subscription's lifetime or only about per-event execution. |
| 332 | + |
| 333 | +## Notes and Limitations |
| 334 | + |
| 335 | +- Tracing relies on `node:diagnostics_channel`. Node, Deno, and Bun expose it; |
| 336 | + browsers do not, where tracing is a no-op. |
| 337 | +- `graphql:parse`, `graphql:validate`, and |
| 338 | + `graphql:execute:variableCoercion` are sync-only channels. They only emit |
| 339 | + `start`/`end`, plus `error` if the traced call throws. |
| 340 | +- Some GraphQL errors are returned in a context `result` rather than through |
| 341 | + the tracing `error` lifecycle event. See |
| 342 | + [GraphQL Errors and Tracing Errors](#graphql-errors-and-tracing-errors) for |
| 343 | + the returned-error channels and the resolver-error wrinkle. |
| 344 | +- These channels report observability events. They are not hooks for altering |
| 345 | + execution; mutating a context payload does not change GraphQL.js behavior. |
0 commit comments