Instrumenting PostgreSQL Queries with OpenTelemetry

Instrument the driver — psycopg, pg, or the JDBC wrapper — before any connection pool is created, enable SQL comment propagation so pg_stat_activity carries the trace ID, and wrap pool acquisition in its own span so queue wait never masquerades as query time.

Context and when it matters

PostgreSQL is usually the largest single contributor to request latency and the least visible part of a trace. The database’s own tooling — pg_stat_statements, the slow-query log, EXPLAIN — is excellent, but it lives in a different universe from your traces: it knows queries, not requests. When the slow-query log is empty and the endpoint is slow anyway, the time is in connection acquisition, row fetching, or transaction boundaries, none of which the database counts as query time.

Proper instrumentation closes that gap in both directions. A trace tells you which request issued which statements and how long each took from the client’s perspective, and comment propagation lets a database administrator take a query they see running and find the request that issued it.

Where the time actually goes

What a client span covers versus what the database measures A horizontal timeline of a single database call totalling 240 milliseconds. Pool acquisition takes 180 milliseconds, the network round trip 4 milliseconds, server execution 38 milliseconds, and row fetch 18 milliseconds. A bracket shows that the database's own slow query log only sees the 38 millisecond execution segment. 240 ms at the client · 38 ms at the database pool acquisition · 180 ms execution · 38 ms fetch · 18 ms net all the database can see what the client span reports Without an acquisition span, this looks like a 240 ms query and the DBA correctly reports that no query took 240 ms. With one, the trace immediately says "the pool is starved" instead of "the database is slow".

Implementation

Patch first, pool second

# main.py — the ordering that decides whether you get spans at all.
from opentelemetry.instrumentation.psycopg import PsycopgInstrumentor

PsycopgInstrumentor().instrument(
    # Appends /*traceparent='...'*/ to every statement — this is what makes
    # pg_stat_activity joinable to your traces.
    enable_commenter=True,
    commenter_options={
        "db_driver": True,
        "opentelemetry_values": True,   # traceparent goes into the comment
    },
)

# Only now import modules that construct pools. A pool built before this line
# captured references to the unpatched driver and will emit nothing.
from app.db import pool  # noqa: E402

The Node.js equivalent has the same constraint, and the same trap of a module-level pool:

// tracing.js — must be required before ./db, e.g. via node --require ./tracing.js
const { PgInstrumentation } = require('@opentelemetry/instrumentation-pg');

registerInstrumentations({
  instrumentations: [
    new PgInstrumentation({
      // Attach the statement — parameterized only — to the span.
      enhancedDatabaseReporting: true,
      addSqlCommenterCommentToQueries: true,
      // Skip the pool's internal keepalive queries; they are noise.
      requireParentSpan: true,
    }),
  ],
});

requireParentSpan is worth knowing about: it suppresses database spans that have no active parent, which removes background health checks and connection validation from your traces without suppressing anything a request actually caused.

Make acquisition visible

from contextlib import contextmanager
from opentelemetry import trace

tracer = trace.get_tracer("app.db.pool")

@contextmanager
def acquire(pool):
    with tracer.start_as_current_span("db.pool.acquire") as span:
        span.set_attribute("db.client.connection.pool.name", pool.name)
        span.set_attribute("db.client.connection.pool.max", pool.maxconn)
        idle_before = pool.idle_count()
        span.set_attribute("db.client.connection.idle_before", idle_before)
        conn = pool.getconn()             # blocks here when saturated
        # An acquisition that blocked is the single clearest capacity signal
        # you can put in a trace.
        span.set_attribute("db.pool.blocked", idle_before == 0)
    try:
        yield conn
    finally:
        pool.putconn(conn)

Join a trace to the database’s own view

With comment propagation on, the statement PostgreSQL sees carries the trace ID:

-- What a DBA sees in pg_stat_activity while the query is running
SELECT pid, state, wait_event_type, query
FROM pg_stat_activity
WHERE state = 'active' AND query LIKE '%traceparent%';

--  pid  | state  | wait_event_type |  query
-- ------+--------+-----------------+----------------------------------------------
--  8213 | active | Lock            | SELECT * FROM orders WHERE tenant_id = $1
--       |        |                 | /*traceparent='00-4bf92f35...-00f067aa...-01'*/

That single line closes the loop: paste the trace ID into the trace UI and you have the request, the user, the endpoint, and every other operation that request performed. It is the cheapest correlation win available in a database-heavy system, and it costs a comment on each statement.

The trace ID as a join key between traces and the database The application span carries a trace ID. The driver appends it as a SQL comment. PostgreSQL records the comment in pg_stat_activity and the slow query log. A database administrator copies the trace ID back into the trace UI and recovers the full request context. One identifier, two toolchains span trace_id 4bf92f… SQL comment /*traceparent=…*/ pg_stat_activity + slow query log trace UI full request DBA finds a blocking query → recovers the exact request that issued it The comment adds ~70 bytes per statement and does not change the query plan, since PostgreSQL ignores comments when planning.

Prepared statements, transactions, and fetch

Three PostgreSQL-specific behaviours change what the spans mean:

Prepared statements split into a prepare and an execute. Some instrumentation records only the prepare, so a statement executed a thousand times shows one span. Check by counting spans against a known workload; if the count is short, enable per-execute spans or accept that repeated executions are invisible.

Transactions span multiple statements. BEGIN and COMMIT are separate round trips, and the time between them — during which locks are held — belongs to no span unless you create one. A wrapping span named for the transaction’s purpose makes lock contention visible and is usually the difference between diagnosing a deadlock in minutes rather than hours.

Server-side cursors stream rows, so the query span ends when the first batch returns rather than when iteration completes. If a request fetches 50,000 rows lazily, the span under-reports its true cost substantially. Wrap the iteration, or record db.response.returned_rows so the discrepancy is at least explainable.

Verification

# One request, one trace: are the spans the shape you expect?
grep '"trace_id": "4bf92f' /var/log/app/otel.jsonl \
  | jq -r 'select(.name | startswith("SELECT") or startswith("db.pool"))
           | "\(.name)\t\(.duration_ms)ms\tparent=\(.parent_span_id != null)"'

# SELECT orders     41ms   parent=true
# db.pool.acquire  180ms   parent=true    ← the real problem

Confirm four things: every database span has a parent; db.query.text contains placeholders rather than values; acquisition appears as its own span; and the trace ID appears in pg_stat_activity for a long-running query.

Reading the resulting trace

Once the instrumentation is right, three shapes recur often enough to be worth recognising on sight.

A wide acquisition span before a fast query. The pool is saturated. The fix is capacity — more connections, a pooler such as PgBouncer, or fewer connections held open — and never query tuning. This is the shape that most often gets misdiagnosed, because the endpoint is slow and the database is idle, which looks like a database problem to everyone except the person reading the trace.

Many short identical queries. An N+1, covered in detecting N+1 queries from trace waterfalls. The count is the diagnostic, not the duration.

One long query with a large row count. Either the query genuinely needs tuning, or it is fetching far more than the caller uses. db.response.returned_rows distinguishes them immediately: fifty thousand rows returned to render twenty is a code problem, while a thousand rows taking four seconds is an index problem.

A fourth shape is worth watching for because it is easy to miss: a gap between a query ending and the next span starting, repeated throughout the request. That is usually row fetching or result processing in the application, and it means the client, not the database, is the bottleneck — a possibility that rarely gets considered because the trace shows database spans and everyone’s attention goes there.

Once these shapes are familiar, the diagnosis for most database-related latency reports takes under a minute, and the argument about whether it is a database problem or an application problem is settled by the trace rather than by seniority.

Four database trace shapes and what each means wide acquire, fast query pool starved *add capacity, not indexes many identical queries N+1 eager load or batch one long query, huge row count fetching too much *narrow the projection gaps between query spans client-side processing instrument the application Four database trace shapes and what each means shape meaning action wide acquire, fast query pool starved add capacity, not indexes many identical queries N+1 eager load or batch one long query, huge row count fetching too much narrow the projection gaps between query spans client-side processing instrument the application Recognising the shape takes seconds and settles the 'is it the database' argument with evidence.

Common pitfalls

  • Pool constructed at import time. The most common reason for zero database spans. Instrument before importing anything that opens connections.
  • Comment propagation on a heavily prepared workload. Adding a distinct comment to each execution can defeat statement caching in some drivers. Verify pg_stat_statements still groups queries after enabling it.
  • Recording the interpolated statement. Leaks data and destroys grouping — see capturing SQL statements without leaking data.
  • Missing server.address on read replicas. Without it, primary and replica queries are indistinguishable and replica lag is invisible.
  • Ignoring span volume. Twenty database spans per request at 500 RPS is 10,000 spans/second from one service — the dominant term in your storage sizing.

A final note on cost: database spans are usually the largest single contributor to span volume in a data-heavy service, and the statement text is the largest field on each one. Truncating statements to a few hundred characters preserves every shape above while cutting export bandwidth substantially — worth doing before the volume becomes a budget conversation.

Related

↑ Back to Instrumenting Databases and Cache Clients