Skip to content

Timing and Tracing Async GraphQL Resolvers

A slow GraphQL request is the sum and overlap of many resolvers, and HTTP-level metrics cannot say which. Per-resolver timing can, at a cost proportional to the number of fields — and GraphQL responses routinely contain tens of thousands of fields. The cost of each approach therefore matters as much as what it reports. Measured with Strawberry 0.329 on Python 3.14, on a query returning 1,000 users and 10,000 posts — 32,000 fields, with async resolvers for both lists: execution took 95.7 ms with no extension (2.99 µs per field); 120.6 ms with an extension that timed every resolver (3.77 µs); 109.0 ms with one that timed only resolvers returning awaitables (3.41 µs); and 453.0 ms with Strawberry's built-in OpenTelemetryExtension (14.16 µs), which created 1,004 spans per request. This guide gets per-field visibility without paying for it on every field.

Prerequisites

1. Time resolvers with a schema extension

Strawberry's SchemaExtension.resolve hook wraps every field resolution. A resolver may return a plain value or an awaitable, so the extension must time both shapes:

import inspect
import time
from collections import defaultdict

from strawberry.extensions import SchemaExtension

FIELD_TIME: dict[str, float] = defaultdict(float)


class ResolverTimer(SchemaExtension):
    def resolve(self, _next, root, info, *args, **kwargs):
        start = time.perf_counter()
        result = _next(root, info, *args, **kwargs)
        key = f"{info.parent_type.name}.{info.field_name}"
        if inspect.isawaitable(result):
            async def timed():
                try:
                    return await result
                finally:
                    FIELD_TIME[key] += time.perf_counter() - start
            return timed()
        FIELD_TIME[key] += time.perf_counter() - start
        return result

Measured: 120.6 ms against 95.7 ms without it — about 0.8 µs added per field, a quarter more execution time. The hook runs for every field, including the 30,000 plain attribute fields (id, title, likes) whose timing is meaningless: they resolve in well under a microsecond and return no awaitable. For an async resolver, the measured time spans from the call to the end of the await, so it includes time spent waiting for the event loop as well as the resolver's own I/O, which is what a caller experiences.

Verify: after a request, the field-time map contains entries for your async resolvers with plausible durations.

Executing 32,000 fields with each instrumentation 4 horizontal bars comparing no extension with the others. Executing 32,000 fields with each instrumentation no extension 95.7 ms (2.99 us/field) time async resolvers only 109.0 ms (3.41 us/field) time every resolver 120.6 ms (3.77 us/field) OpenTelemetryExtension 453.0 ms (14.16 us/field) Strawberry 0.329, Python 3.14; best of 5; 1,000 users with 10 posts each. Instrumentation that touches every field is paid on every field.

2. Time only the fields that do I/O

The fields worth timing are the ones that wait: resolvers that query a database, call a service or await a loader. They are exactly the ones that return awaitables, so the extension can skip everything else at the cost of one isawaitable check:

class AsyncResolverTimer(SchemaExtension):
    def resolve(self, _next, root, info, *args, **kwargs):
        result = _next(root, info, *args, **kwargs)
        if not inspect.isawaitable(result):
            return result                              # attribute fields: no timing work
        start = time.perf_counter()
        key = f"{info.parent_type.name}.{info.field_name}"

        async def timed():
            try:
                return await result
            finally:
                RESOLVER_SECONDS.labels(field=key).observe(time.perf_counter() - start)
        return timed()

Measured: 109.0 ms, or about 0.4 µs per field over the baseline — half the cost of timing everything, with the same useful information. Exporting per-field histograms labelled by Type.field gives each resolver a latency distribution in the same system as the rest of the service's metrics, as in exporting Prometheus metrics from asyncio. Label by field, never by argument values or IDs, or the metric's cardinality explodes.

Verify: the number of distinct label values equals the number of async resolvers in the schema, not the number of requests.

3. Understand what the OpenTelemetry extension costs

Strawberry ships an OpenTelemetryExtension that creates a span for the operation, for parsing and validation, and for each resolver it considers non-trivial:

from strawberry.extensions.tracing import OpenTelemetryExtension

schema = strawberry.Schema(query=Query, extensions=[OpenTelemetryExtension])

Measured with an in-process exporter that only counted spans: 453.0 ms for the 32,000-field query — 4.7 times the uninstrumented 95.7 ms — and 1,004 spans per request, one for each of the 1,000 posts resolver calls plus the request-level spans. With a real exporter, every span is also serialized and sent, so the cost lands both on the request and on the tracing backend. For small queries the overhead is negligible and the trace is genuinely useful; for list-heavy queries it multiplies with the number of async resolver calls. Sampling, as in sampling traces in high-throughput async services, reduces export cost but the extension still does its per-field work on unsampled requests unless spans are suppressed entirely.

Verify: with the extension enabled, compare p99 latency of your largest list query with and without it; if the gap is material, use the lighter extension for per-field data and keep OpenTelemetry for request-level spans.

Three ways to see inside a GraphQL request A grid of 3 rows by 3 columns. Three ways to see inside a GraphQL request approach added per field what you get time every resolver +0.8 us totals per field, mostly noise time async resolvers only +0.4 us histograms of the fields that wait OpenTelemetryExtension +11.2 us per-call spans: 1,004 per request Measured against a 2.99 us/field baseline on the same 32,000-field query.

4. Record request-level spans, sampled field detail

A practical split keeps the request trace in OpenTelemetry and the field-level data in metrics, with one span per loader batch rather than per resolver call:

from opentelemetry import trace

tracer = trace.get_tracer("graphql")


async def load_posts_by_author(pool, author_ids: list[int]) -> list[list[Post]]:
    with tracer.start_as_current_span("db.posts_by_author", attributes={"batch.size": len(author_ids)}):
        rows = await pool.fetch(
            "SELECT id, author_id, title, likes FROM gql_post WHERE author_id = ANY($1::int[])",
            list(author_ids))
    return group_by_author(rows, author_ids)


class OperationSpan(SchemaExtension):
    def on_operation(self):
        with tracer.start_as_current_span("graphql.operation") as span:
            yield
            span.set_attribute("graphql.operation.name", self.execution_context.operation_name or "")

A batched loader runs once per nesting level, so the trace for the 1,000-user query contains a handful of spans that show where the time went — the operation, the users query, the posts batch — instead of a thousand nearly identical resolver spans. The batch-size attribute shows how well DataLoader batching is working, per request, which per-resolver spans cannot. Context propagation into the loader works because contextvars follow the tasks Strawberry creates, as covered in carrying contextvars across threads and executors.

Verify: a trace of a list-heavy query has spans proportional to its nesting depth, not to its number of items.

5. Use the timings to decide what to fix

Per-field timing is only worth its cost if it drives decisions. Three questions it answers that nothing else does:

# Which fields dominate latency? Sum per-field time per operation, sort descending.
top = sorted(FIELD_TIME.items(), key=lambda kv: kv[1], reverse=True)[:10]

# Which fields are called far more often than expected? (an N+1 without a loader)
# -> a resolver count per field per request that tracks list sizes.

# Is the time in resolvers or in execution overhead?
# -> wall time minus the maximum concurrent resolver time ~ fields x ~3 us of executor work.

A field with large total time and a call count equal to a list's length is an N+1 that needs a loader, as in batching GraphQL resolvers with DataLoader. A request whose wall time far exceeds its slowest resolver chain, with tens of thousands of fields, is paying execution overhead — about 3 µs per field measured here — and needs pagination, not faster resolvers. And a single slow field among fast siblings is a dependency to bound with a timeout or to move behind a cache.

Verify: for your three slowest operations, the timing data names a specific field or a field count as the cause.

Which instrumentation fits this API? A decision on What do typical responses look like with 4 outcomes. Which instrumentation fits this API? What do typical responses look like? small, few fields OpenTelemetryExtension full per-call traces large lists, many fields async-only timer + batch spans +0.4 us/field investigating one operation full timing, temporarily +0.8 us/field every API operation-level span always on Measure what waits; trace what batches.

Verification

GraphQL resolver timing is useful and affordable when:

  • Only awaitable-returning resolvers are timed, into per-field histograms labelled by Type.field.
  • Traces carry one span per loader batch, with the batch size, rather than one per resolver call.
  • OpenTelemetry's per-resolver extension is used where responses are small, or its overhead has been measured and accepted.
  • Timing data maps slow operations to a field or a field count.

Diagnostic Hook: chart resolver calls per request per field next to that field's p99 latency. Calls that scale with response size identify missing loaders; a p99 that rises while calls stay flat identifies a slowing dependency.

Pitfalls & edge cases

  • Instrumenting every field. Measured: up to 4.7x slower execution with per-resolver spans.
  • Timing sync attribute fields. They add overhead and no information.
  • High-cardinality labels. Label by field name, never by argument values.
  • Ignoring executor overhead. At about 3 µs per field, large responses are slow without any slow resolver.

Frequently Asked Questions

How do I measure resolver performance in Strawberry GraphQL?

Write a SchemaExtension whose resolve hook times awaitable results and records them per Type.field. Timing only async resolvers added about 0.4 µs per field on a 32,000-field query in testing.

How much overhead does Strawberry's OpenTelemetryExtension add?

On a query returning 32,000 fields it took execution from 95.7 ms to 453.0 ms and created 1,004 spans per request. It is fine for small queries and costly for list-heavy ones.

How do I trace GraphQL without a span per resolver?

Keep an operation-level span and add spans in DataLoader batch functions with the batch size as an attribute; the trace then grows with nesting depth, not item count.

Why is my GraphQL query slow when every resolver is fast?

Execution overhead of about 3 µs per field: a response with tens of thousands of fields spends most of its time in the executor. Paginate.