Identifying Slow Database Queries in Traces

A slow database query surfaces in a trace as a child span whose db.system and db.statement attributes name the operation and whose duration dominates its parent’s self-time — and an N+1 pattern surfaces as many identical such spans running back-to-back under one parent.

Context and When It Matters

Once critical path analysis points at a service as the latency bottleneck, the next question is almost always which query. Database calls are the most frequent leaf on a critical path: they are I/O-bound, they fan out into N+1 patterns under ORMs, and they hide connection-pool waits inside what looks like execution time. Auto-instrumented database client spans give you the raw material to answer the question without adding a single print statement — every query becomes a span carrying standardised semantic-convention attributes you can filter and aggregate on. This page shows how to turn those spans on, read the attributes that matter, spot the two dominant failure shapes, and query Jaeger or Tempo for the offenders across your whole traffic.

Minimal Working Instrumentation

The database instrumentations plug into your existing driver, so the code footprint is tiny. For a Python service on SQLAlchemy or raw psycopg, enabling query spans is a one-liner per integration.

# pip install opentelemetry-instrumentation-sqlalchemy \
#             opentelemetry-instrumentation-psycopg
from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor
from opentelemetry.instrumentation.psycopg import PsycopgInstrumentor
from sqlalchemy import create_engine

engine = create_engine("postgresql+psycopg://app@db/orders")

# Wrap the engine: every statement executed through it now emits a span
# carrying db.system, db.statement (parameterised), and db.name.
SQLAlchemyInstrumentor().instrument(engine=engine)

# Or, for code that uses psycopg directly without SQLAlchemy:
PsycopgInstrumentor().instrument()

That is the whole setup, assuming the OpenTelemetry SDK is already configured to export spans. From here on, every query the engine runs appears in the trace waterfall as a child span nested under whatever business-logic span was active when the query fired — which is exactly the parent-child linkage the critical path walk needs.

The Node.js equivalent is the same shape. For a better-sqlite3 or pg client under the auto-instrumentation ecosystem:

// npm i @opentelemetry/instrumentation-pg
const { PgInstrumentation } = require('@opentelemetry/instrumentation-pg');
const { registerInstrumentations } = require('@opentelemetry/instrumentation');

registerInstrumentations({
  instrumentations: [
    new PgInstrumentation({
      // Off by default for safety: the statement is captured as the
      // span NAME only unless you opt in to the full text as an attribute.
      enhancedDatabaseReporting: false,
    }),
  ],
});

Implementation: Reading the Attributes That Matter

A database span is only useful if you know which attributes to read and what each one means for debugging. The OpenTelemetry semantic conventions standardise the important ones, so a query filter written against them works across Postgres, MySQL, and SQLite alike.

with tracer.start_as_current_span("load_order") as span:
    # The instrumentation creates a CHILD span automatically for the query below.
    # You do not create it — you only read its attributes later in the backend.
    rows = session.execute(
        # db.statement is recorded as: "SELECT * FROM orders WHERE user_id = ?"
        #   -> the ? placeholder is kept; the bound value 4711 is NOT stored.
        select(Order).where(Order.user_id == user_id)
    ).all()
    # Attributes the instrumentation stamps on the auto-created query span:
    #   db.system      = "postgresql"   -> which engine (filter target)
    #   db.name        = "orders"       -> logical database / schema
    #   db.statement   = "SELECT ... ?" -> parameterised SQL, safe to store
    #   db.operation   = "SELECT"       -> verb, cheap to aggregate on
    #   server.address = "db.internal"  -> which instance served it
    span.set_attribute("app.order_count", len(rows))  # your own low-cardinality tag

The load-bearing attribute for finding slow queries is the span’s duration combined with db.statement. Duration tells you the cost; db.statement tells you what to fix. db.operation and db.system are the low-cardinality fields you group and filter on, because the full statement text is too high-cardinality to aggregate cheaply. The single most important rule is what db.statement must not contain: the bound parameter values. The instrumentation stores WHERE user_id = ?, never WHERE user_id = 4711, which is what keeps user identifiers and other PII out of your trace payloads.

Spotting the N+1 Signature

An N+1 is not one slow span; it is a crowd of fast ones. Under an ORM, iterating a collection and touching a lazily-loaded relation on each element issues one query per element. In the waterfall this renders as a picket fence: dozens of narrow, identically-named child spans stacked end-to-end under a single parent.

# ANTI-PATTERN that produces an N+1 in the trace:
orders = session.execute(select(Order)).scalars().all()   # 1 query -> 1 span
for order in orders:
    # Each access issues a SEPARATE query -> N more spans, all identical,
    # all running serially. 50 orders => 51 database spans on the critical path.
    print(order.customer.name)   # lazy load fires "SELECT ... FROM customers WHERE id = ?"

# FIX: eager-load in one round trip -> collapses 51 spans into 2.
orders = session.execute(
    select(Order).options(selectinload(Order.customer))
).scalars().all()

Verification: Querying the Backend for Offenders

Confirm the pattern holds beyond one trace by asking the backend directly. In Tempo, TraceQL filters on the semantic-convention attributes and lets you threshold on duration:

{ span.db.system = "postgresql" && duration > 200ms }

To surface N+1s specifically, count same-statement spans per trace — a trace with twenty spans sharing one db.statement is the fingerprint:

{ span.db.statement = "SELECT * FROM customers WHERE id = ?" } | count() > 10

In Jaeger, filter the trace list by the db.statement tag and sort by duration, then open a representative trace and confirm the query span sits on the critical path rather than in a parallel branch with slack. A slow query that is off the critical path is not your bottleneck, however alarming its duration — which is why this step pairs with the critical path analysis that identified the service in the first place.

Decision Criteria

Use this checklist to turn a suspicious database span into an actionable finding:

  • Is the span on the critical path? If it runs in parallel with a longer sibling, tuning it will not move response time. Verify placement before you optimise.
  • One fat span or many thin ones? A single high-duration span means tune the query — add an index, rewrite the plan, cache the result. Many identical serial spans mean an N+1 — batch, join, or eager-load.
  • Does span duration match the database’s own timing? If the span is far slower than the engine reports for the same statement, the cost is connection-pool checkout or network, not the query. Separate the two before blaming the SQL.
  • Is the statement high-cardinality by design? A statement with an IN (?, ?, ?, …) clause whose placeholder count varies per call explodes into many distinct db.statement values. Normalise it or accept that aggregation will be noisy.

Common Pitfalls

  • Logging bound parameters turns traces into a PII store. Enabling “full statement” reporting that interpolates literal values, or adding your own span.set_attribute("query.args", params), writes emails, tokens, and user IDs straight into spans that are broadly readable. Keep to the parameterised db.statement and read security boundaries in distributed tracing before overriding the default.
  • Using raw SQL as the span name explodes cardinality. If the instrumentation names spans after the full statement text, every distinct literal produces a new span name, which wrecks aggregation in the backend and inflates index size. Prefer the db.operation verb plus table as the name, and keep the full text in the db.statement attribute where it belongs.
  • Connection-pool wait misattributed as query time. When the pool is exhausted, the database span’s duration is dominated by the time spent waiting to acquire a connection, not executing SQL. You will “optimise” a query that was never slow. Wrap pool checkout in its own span, or compare against the engine’s statement timing, so wait and execution are distinguishable.

FAQ

Does db.statement leak sensitive data into traces?

It can, but the OpenTelemetry database instrumentations record the parameterised statement with placeholders, not the bound values. The text stored is UPDATE users SET email = ? WHERE id = ?, never the actual email or id. The risk appears only if you disable parameterisation, log the values yourself, or interpolate literals into the SQL string before it reaches the driver. Keep bound parameters out of span attributes.

How do I tell an N+1 query pattern from one slow query in a trace?

A single slow query is one wide database span with high self-time. An N+1 is many narrow same-named database spans running back-to-back under one parent — a picket fence. Group child spans by db.statement and count repeats: a high repeat count of an identical statement executed sequentially is the N+1 signature, and the fix is a batched query or a join, not tuning the individual statement.

Why does a database span look slow when the query itself is fast?

The span usually wraps connection acquisition as well as execution. If the connection pool is exhausted, the span duration is dominated by checkout wait, not query time. The database reports a fast query while the trace shows a slow span. Add a distinct span around pool checkout, or compare the span duration against the database’s own statement timing to separate wait from execution.

↑ Back to Finding Latency Bottlenecks with Critical Path Analysis