@logaretm is attempting to deploy a commit to the The GraphQL Foundation Team on Vercel.

A member of the Team first needs to authorize it.

The committers listed above are authorized under a signed CLA.

• ✅ login: logaretm / name: Abdelrahman Awad (00a8738, 07a6288, 0d11c3b, 19112ed, 1fa6379, 2309c3e, 24358a8, 25a5cf1, 35fe42d, 362a8f9, 756626b, 7762b22, 7854449, 911b18b, 9228b6a, 9817438, 9eab236, a360947, d11adda, d95a92e, e635746, ea057f6, f0b9ebc, f523acc)
• ✅ login: yaacovCR / name: Yaacov Rydzinski (03c2d3c, 0431c82, 0c80e32, 14ef35f, 1c2e781, 1efb098, 27a1e37, 2c4873a, 2c5383d, 392c342, 426a6e5, 56eba6a, 652d18c, 7a0f75c, 8001e21, 84e3e6c, 87841f7, 925ab7e, 9d3a1e2, af3493c, b02b459, b26038e, b6de256, b776e27, b9b1a5a, c3b3291, c469499, d8a2b25, de0fabe)

The implemented channels are...

Please excuse my limited understanding of the current tracing space, but is there a concept of nesting of channels? In theory, I would expect we would want to:

(1) nest the "execute" channel for subscription events under "subscribe" and
(2) nest "resolve" under "execute"

Naively, I would assume this would be very useful information to understanding the hierarchy.

And I would think this would provide a way to pass the overarching context of the subscribe option to execute (i.e. execute would always have the document, as in your description of the channels/context within the linked issue #4629)?

And similarly, we could also have the overall execute (or subscribe/execute) passed to resolve?

@yaacovCR Happy to elaborate more!

is there a concept of nesting of channels?

From a purely diag/tracing channels API perspective, there's no parent/child relationship in the API. Each channel is independent. graphql:execute and graphql:resolve don't know about each other at the module level.

That said, the hierarchy you're describing does exist at runtime, it's just reconstructed on the subscriber side rather than on the emitter side. The mechanism is done through AsyncLocalStorage:

You can check the image I had in the PR description that represents how it looks like, or check this trace view as you can see the spans are nested under one another.

This works because tracing channels propagate the async execution context (unlike plain event emitters). Subscribers bind an AsyncLocalStorage to the channel, and every downstream channel fired under that sees the same store via async_hooks. Think of it as an implicit requestId threaded through by the runtime.

It's why I kept the runStores wrapper in the types and impl even after dropping tracePromise. TracingChannel.traceSync/tracePromise wrap runStores for you, but we roll the lifecycle manually here to handle the mixed sync-or-promise return path cleanly, so we need to call runStores ourselves to preserve ALS propagation.

Now, for graphql as the emitter, there are a couple of reasons not to encode the hierarchy ourselves:

• GraphQL wouldn't know if the channels are nested, unless we implement logic that does that or use ALS ourselves but that's strictly a node API that's not polyfillable.
• We'd have to track the hierarchy unconditionally even when nothing is subscribed because we don't know at emit time whether a subscriber cares. That defeats the hasSubscribers short-circuit we use on the hot paths today.
• Subscribers can attach to one channel or several or all of them. If graphql baked the hierarchy into the ctx object, we risk breaking it for those partial subs.

The good news is subscribers will have access to document and other parent event objects naturally through their ALS if they want to, graphql doesn't have to do it and subscribers get it for free.

Here is a quick example snippet:

import { AsyncLocalStorage } from 'node:async_hooks';
import dc from 'node:diagnostics_channel';
import { enableDiagnosticsChannel } from 'graphql';

enableDiagnosticsChannel(dc);

const executeCtx = new AsyncLocalStorage();

const executeChannel = dc.tracingChannel('graphql:execute');
const resolveChannel = dc.tracingChannel('graphql:resolve');

// Bind on `start` only, the store activates when execute's runStores frame
// opens and stays active through the entire lifecycle. `end`, `asyncStart`,
// `asyncEnd`, and `error` all fire inside that frame (sync handlers directly,
// async ones via async_hooks propagation), so they inherit the same store
// without any extra wiring.
executeChannel.start.bindStore(executeCtx, ctx => ({
  document: ctx.document,
  operationName: ctx.operationName,
  startedAt: Date.now(),
}));

// Subscribe to the full execute lifecycle. Every handler sees the same store.
executeChannel.subscribe({
  start: () => {
    const { operationName } = executeCtx.getStore();
    console.log(`[execute:start] ${operationName}`);
  },
  end: () => {
    const { operationName, startedAt } = executeCtx.getStore();
    console.log(`[execute:end]   ${operationName} (+${Date.now() - startedAt}ms sync)`);
  },
  asyncStart: () => {
    const { operationName } = executeCtx.getStore();
    console.log(`[execute:asyncStart] ${operationName}`);
  },
  asyncEnd: () => {
    const { operationName, startedAt } = executeCtx.getStore();
    console.log(`[execute:asyncEnd]   ${operationName} (+${Date.now() - startedAt}ms total)`);
  },
  error: ({ error }) => {
    const { operationName } = executeCtx.getStore();
    console.log(`[execute:error] ${operationName} -> ${error.message}`);
  },
});

// Nested channels inherit the parent's store too, because resolve fires
// beneath execute's runStores frame.
resolveChannel.subscribe({
  start: resolveCtx => {
    const parent = executeCtx.getStore();
    console.log(`  [resolve:start] ${resolveCtx.fieldPath} (under ${parent.operationName})`);
  },
  asyncEnd: resolveCtx => {
    const parent = executeCtx.getStore();
    console.log(`  [resolve:asyncEnd] ${resolveCtx.fieldPath} (under ${parent.operationName})`);
  },
  error: ({ error }, name) => {
    const parent = executeCtx.getStore();
    console.log(`  [resolve:error] under ${parent.operationName}: ${error.message}`);
  },
});

@yaacovCR Happy to elaborate more!

This was hugely helpful. On this background, I am wondering whether instead of:

Maybe something like the below would be better for our official tracing channels:

The idea would be that subscribe is not really "a thing" according to the spec, and in theory our separate execute and subscribe endpoints are just a way to keep track of the relationship between execute and executeSubscriptionEvent. This would nest executeQueryMutationOrSubscriptionEvent under every execute call for queries, mutations, and subscriptions, with one executeQueryMutationOrSubscriptionEvent for each query/mutation execute, and a variable number of executeQueryMutationOrSubscriptionEvent for a subscription execute.

The downside is you can no longer top-level distinguish between subscriptions and queries/mutations. Do we want to preserve that? Do we want to top-level distinguish between each of our operations? What about between queries and mutations?

Again, I am asking these questions with very little knowledge of how the tracing system is used in practice, hopefully you can guide me here?

Looping in @graphql/tsc if they have any thoughts.

@yaacovCR

Maybe something like the below would be better for our official tracing channels:

We could do graphql:operation as top level and graphql:execute 1x for queries/mutations and N x per sub. Does that track or do we want that lengthy name instead 😅

The downside is you can no longer top-level distinguish between subscriptions and queries/mutations...

The distinction can be done with the args already sent to the execute channel via the operationType property we have right now. Channel level distinction is unlikely to be worth it given how low the overhead is.

I initially added a subscribe channel because it felt like its own thing, but it is better to name channels from GQL's POV, like "I'm doing this thing right here....".

What do u think?

What do u think?

Naming = so hard. Definitely like shorter. But I do prefer consistency with the other verbs we have for our channels.

We could consider:

• execute vs. executeQueryMutationOrSubscriptionEvent (not great if another operation type lands)
• operation vs. execute (not great as operation = noun)
• execute vs. operation (ha! both are not great as it's not clear really which should be the wrapper, although this is incorrect as the nested executeSubscriptionEvent is not an operation, it's more like a sub-operation which is not a thing.)
• executeRequest vs. executeOperation (not correct, a subscription operation does not contain multiple underlying operations, as above)
• executeRequest vs. executeRootSelectionSet (correct and technically disambiguated, as when we execute a single root field to create the source event stream for a subscription, we do not [currently] allow for merging multiple fields by utilizing multiple root fields, so on the subscription side it is [presently] executeSingleAllowedRootField and if we ever change that we could just call that part createSourceEventStream)

I am leaning toward the last option, again looping in better namers @graphql/tsc @graphql/tsc-emeriti

@logaretm

From my machine on 17.x.x I ran:

npm run benchmark -- benchmark/introspectionFromSchema-benchmark.js benchmark/list-sync-benchmark.js benchmark/list-async-benchmark.js benchmark/list-asyncIterable-benchmark.js benchmark/object-async-benchmark.js --revs pr/4670 17.x.x

And got:

1. On our real-world large sync query we got a 7% slowdown. This is the most concerning result.
2. On a synthetic sync query with a lot of list items we got a 23% slowdown, also concerning, although the query is artificial.
3. On synthetic async queries, we were at parity or faster, somehow thanks to this PR and presumably v8 magic!

Not sure if you have any insight. I would assume most of this is secondary to graphql:resolve. Ideally we would of course have no slowdowns at all, at least on these benchmarks when tracing is not enabled.

@yaacovCR I will re-work the PR to use the autoloading snippet and I will dig into the benchmarks and see what I can do, ideally it should offer close to zero slowdown so I must be doing something wrong.

• executeRequest vs. executeRootSelectionSet (correct and technically disambiguated, as when we execute a single root field to create the source event stream for a subscription, we do not [currently] allow for merging multiple fields by utilizing multiple root fields, so on the subscription side it is [presently] executeSingleAllowedRootField and if we ever change that we could just call that part createSourceEventStream)

I am leaning toward the last option, again looping in better namers @graphql/tsc @graphql/tsc-emeriti

Although maybe we should do instead:
graphql:execute and graphql:execute:rootSelectionSet
or even
graphql:execute and graphql:execute:root-selection-set

is there a convention in the diagnostic channels world?

@yaacovCR Not a strict convention, but this is what is currently recommended.

For the names, I think we can keep the inner one called graphql:execute for the outer one, how about:

• graphql:request
• graphql:run
• graphql:process
• graphql:handle

Naming is hard 😅

Not necessarily related, but possibly, what would a trace look like for incremental delivery?

Options abound because of the disconnect between execution groups and delivery groups.

@yaacovCR So I pushed a couple of optimizations, I think it is down significantly after running the benchmark u gave me. It was at 6% overhead at the time of your posting on my machine and now its down to 2.3%-3%.

Can u have a go and see if that's acceptable? I have more ideas but will require juggling alternate Executor class implementations.

Not necessarily related, but possibly, what would a trace look like for incremental delivery?

Right now they aren't handled and any deferred executions will be orphaned (up to the APM how to deal with that) since they will still fire the resolve channels.

So it would look like this:

  time ──────────────────────────────────────────────────────►

  execute   ◄────── runStores frame #1 ──────►
  ├─ resolve fieldA        (#2, parented to #1)  ✓
  ├─ resolve fieldB        (#3, parented to #1)  ✓
  └─ returns {initialResult, subsequentResults}
                      ▲ frame #1 ends here ─ generator has not run yet

          ─── gap: framework owns the generator ───

           await subsequentResults.next()   (fresh async context, no ALS)
                                                                       
  resolve fieldC (@defer)  (#4, ⚠ ORPHANED — no parent span)
  resolve fieldD (@stream) (#5, ⚠ ORPHANED — no parent span)

I think we can keep the current PR scoped to this at the moment, and I can try a follow up if this one goes through. I'm thinking we can add another :group channel, so it looks like:

 time ──────────────────────────────────────────────────────►

  execute   ◄────── runStores frame #1 ──────►
  ├─ resolve fieldA        (#2, parented to #1)  ✓
  ├─ resolve fieldB        (#3, parented to #1)  ✓
  └─ returns {initialResult, subsequentResults}
                      ▲ frame #1 ends

          ─── gap: framework drives the generator ───

           await subsequentResults.next()

  execute:group 'slowDefer'  ◄── runStores frame #4 ──►
  └─ resolve fieldC (@defer) (#5, parented to #4)  ✓

  execute:group 'feed@stream' ◄── runStores frame #6 ──►
  └─ resolve fieldD (@stream) (#7, parented to #6)  ✓

The group events look like extra spans, but their real job is to keep an ALS frame alive while the deferred resolvers run, so anything the APM bound stays readable. I'll verify end-to-end in the follow-up

Squeezed a bit of performance with the last couple of commits 🙌 for the channel names happy to pick whatever works for us here to make this ready to go.

@Qard ATM nested resolvers are not linked together as children, they instead execute and appear as siblings. However they all appear as a child of the execute channel invocation.

I realize this isn't the ideal outcome, I will experiment with expanding the runStores callback to include resolve child recursion and see how it fares in benchmarks.

Ideally we'd want that causality. Might be sufficient to pass the parent resolver info into the child events as that is past into the resolvers themselves. 🤔

@Qard I widened the runStores frame to include the nested resolvers, and got something looking like this

Perf wise, it has the same perf with no subs as the current state, all near 0% diff so it didn't introduce cold paths. Now comparing it against the current impl (no nesting) with subs attached, the numbers are very similar.

So only one case has seen a slow down which I think would come to a wash once an APM does somethings anyways. So we basically get it for free here, WDYT? worth including or maybe let the subscriber stitch it together? (they can with the path information in each call).

@logaretm

1. rebased on 17.x.x
2. stored document along with rawVariableValues on ValidatedExecutionArgs so that execute:rootSelectionSet has access to it.
3. dropped node 20.x support
4. added some coverage
5. pushes a cosmetic TS change

What do you think, anything else you want to round out?

@yaacovCR Nope, pretty happy with this!

@logaretm one last tweak above in 015b959 in direction of your earlier hoisting of shouldTrace for graphql:resolve to executeFields.

I didn't realize when first reviewing this that hoisting in this way should not affect correctness at all, as the value of shouldTrace should not change during this call, so I went back to it. For executeFieldsSerially, the value could change, because we are doing potentially async serial execution, so I call shouldTrace again along that async boundary.

And added a test.

Thoughts?

With this, I'm good to go, from my end.

Next thing would be to add an article to the website discussing it. One central piece for the article would be an updated version of the table above with the channels and context?

The website is published (still) from the 16.x.x branch, but covers both 16.x.x and 17.x.x and we would need to update the What's new in v17 guide perhaps as well. This would also belong in our growing list of "graphql-js runtime features."

Would you like to take a stab at it?

@yaacovCR

I didn't realize when first reviewing this that hoisting in this way [...]

Yep that should be safe, no APM/user should expect to subscribe mid-call or during async continuation ticks as they will get busted async contexts anyways

Next thing would be to add an article to the website discussing it [...]

Yea, I'm happy to. I will create a new PR against 16.x.x with the website/docs updates. Sounds good?

@logaretm

sounds great!

some more changes for your review

1. preserve ancient option of resolvers to return Promise/A+ thenables without finally
2. rename variableValues => rawVariableValues throughout
3. preserve type of rawVariableValues as { [value]: unknown} | null | undefined rather than just { [value]: unknown} | undefined

And here is my update of the overall PR description for use in the merge commit:

This PR implements tracing channel support for graphql-js.

graphql-js resolves node:diagnostics_channel at module load through process.getBuiltinModule. On runtimes where the built-in is unavailable, such as browsers, channel handles are undefined and emission sites short-circuit. APMs subscribe through their own node:diagnostics_channel import by channel name; no GraphQL API call or option is required.

The implementation adds the diagnostics channel helper, internal structural typings for the Node tracing-channel surface, subscriber-facing context types exported from the root package, and wrappers around parse, validate, execute, subscribe, root-selection-set execution, variable coercion, and resolver execution. The no-subscriber path is guarded by shouldTrace/hasSubscribers checks, with a sub-channel fallback for runtimes that do not expose aggregate TracingChannel.hasSubscribers. Traced execution uses runStores to preserve tracing-channel async context propagation, does not normalize synchronous execution to async, and handles promise-like resolver results without Promise.resolve normalization.

Test coverage exercises lifecycle emission, lazy context fields, no-subscriber no-op behavior, missing node:diagnostics_channel behavior, exported context types, promise-like resolver results, and runtime compatibility coverage for Bun and Deno.

API

graphql-js vendors a minimal structural subset of the tracing channel types for internal use so it does not depend on Node typings or on node:diagnostics_channel being present at runtime. It also exports subscriber context types from the root package, including GraphQLChannelContextByName and the per-channel context interfaces.

Each channel publishes lifecycle events through Node tracing channels. The table lists the base context fields present at start; successful sync work adds result by end, successful async work adds result by asyncEnd, and thrown or rejected work adds error on the error lifecycle. Variable coercion is synchronous, so it only emits start/end and error when coercion throws abruptly.

graphql:execute:variableCoercion publishes the caller-provided values as rawVariableValues; its successful result contains the coerced { variableValues }, or { errors } when coercion returns request errors.

graphql:execute:rootSelectionSet fires once for the operation root selection set. For subscriptions, it fires once per emitted subscription event, matching the OTel graphql.subscription.event shape; subscribers can distinguish operation kinds through operationType.

Usage

import dc from 'node:diagnostics_channel';
import type { GraphQLResolveContext } from 'graphql';

dc.tracingChannel('graphql:resolve').subscribe({
  start: (context: GraphQLResolveContext) => {
    // start span
  },
  end: (context: GraphQLResolveContext) => {
    // sync resolver result is available here as context.result
  },
  asyncEnd: (context: GraphQLResolveContext) => {
    // async resolver result is available here as context.result
  },
  error: (context: GraphQLResolveContext) => {
    // report context.error
  },
});

Closes #4629

Changes look good, especially the promise-like preservation. I updated the PR description and will work on the docs/website PR and submit it tomorrow morning.