In a per-field GraphQL trace, what do a resolver span's self time and elapsed time each measure?
answer
- Two numbers per field, not one
- A parent's span contains its children
- Siblings run at the same time
- Subtract what the children took
basics
~20 sElapsed is wall clock from the moment the executor invokes the field's resolver until that field's value is complete, so it includes every child field. Self time subtracts the children, leaving the field's own work. Rank by self time.
solid answer
~50 sA per-field trace opens a span when the executor calls a field's resolver and closes it when that field's value is fully completed. For an object or list field, completion includes resolving everything underneath, so **elapsed is inclusive** — the span for `performance.seatMap` covers every section, row and seat below it. **Self time** is elapsed minus the time attributable to children, which is the only number that tells you where the work actually happened. Two traps follow. Sibling fields at the same level are usually resolved concurrently, so their elapsed times overlap and summing them will exceed the request duration — never build a pie chart out of elapsed. And if the tracer closes the span when the resolver *returns* rather than when its returned future settles, all the awaited work falls outside the span and the slow field looks free.
code
graphql · 17 linesquery SeatMap($performanceId: ID!) {
performance(id: $performanceId) {
id
seatMap {
sections {
name
rows {
label
seats {
number
status
}
}
}
}
}
}go deeper
Be ready to state that one number includes everything below the field and the other does not, and to say which of the two you would sort by when hunting a slow resolver. That distinction alone is the recall being checked.
Explain the mechanics: when the span opens and closes relative to value completion, why sibling concurrency makes elapsed unsummable, and how self time is derived by subtracting child intervals rather than measured directly.
Demonstrate that you distrust the numbers. Show how a batched fetch parks its wait on one arbitrary sibling, how a span closed at resolver return hides awaited work, and how an implausibly cheap field can be a correctness signal.
Own what the organisation trusts. Decide whether field timings are authoritative enough to drive alerts and budgets, or whether they are a debugging aid only, and set the instrumentation contract so teams are not comparing incompatible numbers.
## What a span is here Per-field tracing instruments the executor rather than the transport. Every time the executor resolves a field, it records an interval: a start instant, an end instant, and enough identity to say which field this was — the parent type and field name from the schema, plus the field's **response path**, the same list of response keys and list indices that a field error would carry. For a ticketing read that is a path like `performance.seatMap.sections.3.rows.11.seats.4.status`. The path matters because one schema field is resolved many times in one request: `status` is a single coordinate in the schema and 1,847 separate spans in this document. ## Elapsed is inclusive Execution is a tree walk. The executor resolves `performance`, gets an object, then resolves its selected sub-fields against that object, and recurses. If the span for a field closes only when that field's **value completion** has finished — which for an object means all its selected children are complete, and for a list means every item is complete — then the span's duration necessarily contains the durations of everything below it. That is what elapsed means: the total wall-clock cost of this subtree. That number answers one question well and another badly. It is exactly right for "how much of the response was this branch responsible for", which is what you want when you are deciding whether to make `seatMap` a separate request. It is useless for "which resolver should I go fix", because the root field will always be the largest and the leaves will always be the smallest. ## Self time is elapsed minus the children Self time is computed, not measured: take the span's elapsed and subtract the time attributable to its child spans. Sort by self time and you get a ranking of the resolvers that actually burned wall clock. Concretely, in a slow ticketing response you might see: - `performance` — elapsed 612 ms, self 3.1 ms - `performance.seatMap` — elapsed 604 ms, self 1.7 ms - `performance.seatMap.sections` — elapsed 598 ms, self 2.4 ms - `performance.seatMap.sections.0.rows` — elapsed 571 ms, self 549 ms The first three are pass-throughs. The whole request is one row fetch under one section, and everything above it is bookkeeping. ## Why elapsed does not sum Most executors resolve the fields of one selection set concurrently, and list items concurrently too. Their spans therefore overlap in real time. If 46 sibling `rows` spans each take 40 ms but run together, they consume roughly 40 ms of wall clock and 1,840 ms of summed elapsed. Any visualisation that adds elapsed values — a pie chart of "time by field", a percentage-of-request column — is nonsense the moment there is concurrency. Self time does not have this problem within a single sibling set only if the tracer is careful about overlap; when in doubt, read the tree as a tree and use the flame shape rather than an arithmetic total. ## The two ways the numbers lie **A future that settles later.** If a resolver returns a promise or a future and the instrumentation stops the clock when the function returns, the span records the cost of *scheduling* the work, not of doing it. You get a trace full of 0.2 ms spans and 600 ms of unattributed request time. Correct instrumentation closes the span when the returned value has been completed. This is the single most common reason a per-field trace "shows nothing". **A waited-on batch.** If a field's data is fetched through a per-request batch loader, the batch is dispatched once and every participating field waits on the same underlying call. Whichever field's span happens to be open when that call resolves absorbs the wait: one seat looks like it cost 180 ms and its 1,846 siblings look free. The distribution is an artefact of the instrumentation, not of the workload, and reading it as "seat 4 is slow" sends you down the wrong hole. ## A near-zero self time is also a signal Self time is usually read from the top of the sorted list, but the bottom is informative too. In one ticketing incident the row-fetch spans under `performance.seatMap.sections.*.rows` showed a self time of 0.4 ms where they normally sat around 38 ms — far too fast for a real fetch. The rows were being served from a response cache keyed on the performance identifier alone, with no viewer in the key, so a viewer could be handed a row carrying another viewer's active seat holds. The latency win was the symptom that exposed a correctness bug: a field that suddenly got cheap is a field that stopped doing the work you thought it was doing. ## What to say in an interview Define both: elapsed is the inclusive wall clock of the field and its whole subtree; self is elapsed minus the children, and it is what you rank. Then volunteer the traps — elapsed does not sum under concurrency, a span that closes on resolver return misses everything awaited, and a batched fetch parks its wait on one arbitrary sibling. Naming those is the difference between having read a trace and having debugged with one.
- You sort by self time and the top entry is a single list item out of 1,847. What do you suspect?Instrumentation artefact before workload. The likeliest cause is that all those siblings share one batched backend call, and whichever span was open when the call settled absorbed the whole wait. Confirm by checking whether the sibling spans have implausibly small self times and whether their intervals all end at the same instant. If they do, the number to optimise is the shared call, not that item.
- A trace shows every field under 1 ms but the request took 700 ms. Where did the time go?Almost certainly outside the spans. Either the tracer closes each span when the resolver returns rather than when the value it returned has been completed, so all awaited work is unattributed, or the time is spent somewhere the field instrumentation does not cover — parsing and validating the document, serialising a large response, or waiting on the transport. Check the request-level span's duration against the sum of the top-level field spans first.
- Is self time something the tracer measures or something you compute?Computed. The instrumentation records intervals with start and end instants and a parent link; self time is derived afterwards by subtracting the intervals attributable to the children. That is why it is only as trustworthy as the parent-child relationships in the trace — if a child span is recorded without its parent, or attached to the wrong parent, the self time of both is wrong even though every raw interval is correct.
Elapsed is the total time a manager's project took, including everyone reporting into it; self time is the hours the manager personally worked. Only the second tells you whether the manager is the bottleneck.
saying these in an interview costs you the question
- Adds elapsed times together to get request time
- Optimises the root field because its elapsed is largest
- Thinks self time is measured rather than derived
- Reads a slow single list item as a slow record
- Assumes a span ends when the resolver function returns
- Treats a suddenly fast field as purely good news