Detecting N+1 Queries from Trace Waterfalls

An N+1 shows up as a run of identically named sibling spans, each fast, whose total duration dominates the request — the diagnostic is span count per request rather than span duration, so a query counting spans by name across many traces finds it faster than reading any single waterfall.

Context and when it matters

The N+1 is the most common performance defect in any application with an ORM, and the one traces are best at finding. It hides from every other tool: each query is fast, so the slow-query log is empty; total database time is high, so the database looks busy for no visible reason; CPU profiles show time in the driver rather than in the query. Only a trace shows two hundred separate round trips where one would do.

It is also the defect most likely to appear without a code change. A query that returned five rows in staging returns two hundred in production, and a page that was fine at launch degrades as data grows — the code is identical, the trace is not.

The signature

The repeated-sibling signature, before and after the fix Above, a request span of 640 milliseconds contains one SELECT orders span followed by twenty short SELECT customers spans in sequence, each about 25 milliseconds, filling most of the request. Below, the fixed version shows the same request at 90 milliseconds with one SELECT orders span and one joined query. Twenty fast queries beat one slow query in every log — and lose in every trace before · 640 ms GET /orders SELECT orders · 14 ms 20 × SELECT customers · 25 ms each · none of them slow after · 90 ms GET /orders SELECT orders JOIN customers · 22 ms Span count went from 21 to 2; request duration went from 640 ms to 90 ms; no individual query got faster. The tell is the shape — a dense run of equal-width siblings — not the duration of any one span.

Confirming it across many traces

One waterfall is suggestive; a count across the population is proof, and it also tells you how bad the tail is.

# Traces where this route issued more than 10 database spans
{ resource.service.name = "storefront" && span.http.route = "/orders" }
  >> { span.db.system.name = "postgresql" }
  | by(span.db.collection.name) | count()

# Distribution of database span counts per trace, to see the tail
{ span.http.route = "/orders" } | count() by (trace:id) | histogram()

The relationship to watch is between span count and request duration. In an N+1 they are linearly correlated — twice the rows, twice the duration — which distinguishes it from a genuinely slow query, where duration varies and count does not.

# Same analysis from the Jaeger API, for backends without aggregation
curl -s -G "http://jaeger-query:16686/api/traces" \
  --data-urlencode 'service=storefront' --data-urlencode 'limit=100' \
  | jq -r '.data[] | {
      trace: .traceID,
      dur_ms: (.spans[0].duration / 1000),
      db_spans: [.spans[] | select(.operationName | startswith("SELECT"))] | length
    } | "\(.trace)\t\(.dur_ms)\t\(.db_spans)"' \
  | sort -k3 -rn | head
# Strong correlation between columns 2 and 3 is the confirmation.

The variants that hide it

Not every N+1 looks like twenty identical siblings. Four variants defeat a naive visual scan:

Nested. The repeated query happens inside a loop that is itself inside a loop, so the siblings are spread across several parents. Counting by name across the trace still finds it; scanning one level does not.

Across services. The loop calls a downstream HTTP API rather than a database. The signature is identical — repeated identical CLIENT spans — and the cost is far higher because each iteration is a network round trip. This is the most expensive variant and the one an ORM-focused mental model misses.

Cached. Most iterations hit a cache and are sub-millisecond; a handful miss and hit the database. The waterfall looks fine until traffic patterns change and the hit ratio drops, at which point the same code becomes catastrophically slow. Recording cache.hit makes this visible before it degrades — see instrumenting Redis clients and cache operations.

Concurrent. The loop runs in parallel, so total duration is short and the spans overlap rather than tiling. The count is unchanged and the database load is unchanged; only the wall-clock symptom is hidden. It is still a hundred queries.

The fixes

# Django — eager load the relation instead of walking it lazily
orders = Order.objects.filter(tenant=tenant).select_related("customer")     # FK
orders = Order.objects.filter(tenant=tenant).prefetch_related("items")      # reverse FK / M2M

# SQLAlchemy
stmt = select(Order).where(Order.tenant_id == tid).options(joinedload(Order.customer))

# Cross-service: batch the calls the loop was making one at a time
async def enrich(order_ids):
    # One request for 200 ids instead of 200 requests for one id each.
    return await client.post("/customers/batch", json={"ids": list(order_ids)})

For the cross-service variant, a batch endpoint is usually a new API. That is a larger change than adding select_related, and the trace is what justifies it: “this endpoint makes 200 sequential calls to your service, each 25 ms” is a concrete argument in a design discussion.

Preventing the regression

Span count rises before latency becomes a complaint Two lines over eight weeks. Database spans per request rise steadily from 4 to 46 as data grows. Request p95 duration stays flat for the first five weeks then rises sharply. An alert threshold at 20 spans per request fires in week four, well before the latency curve turns. Alert on span count, not on latency spans p95 alert threshold · 20 spans/request alert fires users complain week 1 week 8 Span count degrades linearly with data volume; latency stays flat until a threshold, then falls off a cliff. 
# A span-metrics dimension makes the count alertable
connectors:
  spanmetrics:
    dimensions:
      - name: http.route
      - name: db.collection.name
# Database spans per request, by route — alert when it doubles
sum by (http_route) (rate(traces_span_metrics_calls_total{db_collection_name!=""}[10m]))
  / sum by (http_route) (rate(traces_span_metrics_calls_total{span_kind="SPAN_KIND_SERVER"}[10m]))
  > 20

The same check belongs in tests: assert a maximum span count for a request in an integration test, and the regression fails the build rather than the dashboard.

Why it survives code review

Understanding why this defect is so persistent explains why an automated check is worth more than vigilance.

The code that produces an N+1 is usually the clearest way to express the intent. Iterating over orders and reading order.customer.name is exactly what the domain describes; the alternative, an eager-loading hint that must name the relation, is a performance annotation that the reader has to know to look for. The lazy version reads better and is correct in every sense except how many round trips it makes.

It is also invisible at the scale where the code is written. A developer testing with five records sees five extra queries taking two milliseconds. The same code in production iterates two hundred records against a database twenty milliseconds away. Nothing about the code changed between those two situations, so no review of the code could have caught it — only a review of the trace.

And it is reintroduced constantly. Every new relation accessed inside an existing loop, every serializer field that follows a foreign key, every template that renders a related object adds one. A single fix does not protect the endpoint; the pattern returns with the next feature that touches the same view.

That is the argument for the span-count assertion in tests and the span-count alert in production. Both work on the property that actually matters — how many round trips a request makes — rather than on code shape, and both catch the reintroduction rather than only the original. A test asserting that GET /orders issues at most three database spans is a durable statement of intent that survives refactoring, framework upgrades, and the developer who wrote it moving to another team.

N+1 variants and how each hides classic ORM loop 20 identical sibling spans *obvious once you look nested loops spread across parents count by name, not by level cross-service repeated CLIENT spans *most expensive variant mostly cached few misses today breaks when hit ratio drops concurrent overlapping spans same load, shorter wall clock N+1 variants and how each hides variant appearance note classic ORM loop 20 identical sibling spans obvious once you look nested loops spread across parents count by name, not by level cross-service repeated CLIENT spans most expensive variant mostly cached few misses today breaks when hit ratio drops concurrent overlapping spans same load, shorter wall clock Only the first is visible at a glance; the rest need a count query rather than an eye.

Common pitfalls

  • Looking only at slow spans. Every span in an N+1 is fast; sorting by duration hides it completely.
  • Fixing it with a cache. Caching a hundred lookups makes the symptom smaller and leaves a hundred round trips in the code, which return the moment the cache is cold.
  • Missing the cross-service variant. Repeated CLIENT spans to another service are the same bug with a much higher cost per iteration.
  • Assuming concurrency solves it. Parallelising a hundred queries reduces wall-clock time and leaves the load on the database exactly as it was.
  • Not counting spans in tests. The pattern reappears with the next lazy relation someone adds; only an automated count prevents it.

A last diagnostic tip: when the count varies between traces of the same endpoint, plot count against the size of the collection being iterated. A straight line confirms the N+1 and tells you the constant, which is exactly the number a fix has to eliminate.

Related

↑ Back to Finding Latency Bottlenecks with Critical Path Analysis