Tracing PostgreSQL Queries with psycopg

psycopg is the most widely used PostgreSQL driver for Python, and its OpenTelemetry instrumentation produces a client span for every statement with almost no configuration. This page covers enabling it, adding SQL commenting so spans join PostgreSQL's own view of the same query, recording the row counts that separate slow plans from large results, and the connection pools, transactions and bulk operations that statement spans alone do not describe. It is a task article under tracing databases and message queues, part of the distributed tracing and OpenTelemetry in Python section.

Prerequisites

pip install "psycopg[binary,pool]>=3.1.0,<4.0.0" \
            "opentelemetry-instrumentation-psycopg>=0.48b0,<1.0.0" \
            "opentelemetry-sdk>=1.27.0,<2.0.0"

Implementation

Step 1 — Enable the instrumentation before any connection is created. The instrumentor wraps psycopg's connection and cursor classes, so connections opened before it runs are not traced. Calling it at startup, before pools are created, covers everything.

from opentelemetry.instrumentation.psycopg import PsycopgInstrumentor

PsycopgInstrumentor().instrument(
    enable_commenter=True,                      # trace context appended as a SQL comment
    commenter_options={"db_driver": True},
)

Step 2 — Confirm SQL commenting reaches PostgreSQL. With commenting enabled, each statement arrives at the server with a trailing comment carrying the traceparent. PostgreSQL's slow query log and pg_stat_activity show it, which lets a database administrator looking at a slow statement find the request and the code that issued it — and lets an engineer looking at a slow span find what the server did.

SELECT pid, left(query, 120) FROM pg_stat_activity WHERE state = 'active';

Expected Output: an active statement carrying its trace context.

  pid  |                                   left
-------+-------------------------------------------------------------------------
 18422 | SELECT id, sku, price FROM products WHERE id = $1 /*traceparent='00-9f2a71c4f0b8…-4b1e77a2c9de5013-01'*/

Step 3 — Record row counts. A span's duration does not say whether the query was slow to plan or simply returned a great deal. The cursor's rowcount after execution distinguishes them, and a small wrapper records it on the current span. A query taking two seconds and returning fifty thousand rows needs pagination; one taking two seconds and returning one row needs an index.

from opentelemetry import trace

def execute_traced(cur, sql, params=None):
    cur.execute(sql, params)
    span = trace.get_current_span()
    if span.is_recording() and cur.rowcount is not None and cur.rowcount >= 0:
        span.set_attribute("db.response.returned_rows", cur.rowcount)
    return cur

Step 4 — Time pool acquisition separately. psycopg's connection pool hands out connections, and when every connection is checked out, callers wait. That wait happens before any statement span begins, so it shows up in the trace as a gap rather than as a slow query. A span around acquisition makes the gap visible, as developed in observing connection pool exhaustion.

from psycopg_pool import ConnectionPool

pool = ConnectionPool(DSN, min_size=4, max_size=16, timeout=5)
tracer = trace.get_tracer("db")

def with_connection(fn):
    with tracer.start_as_current_span("db.pool.acquire") as span:
        conn_cm = pool.connection()
        conn = conn_cm.__enter__()
        span.set_attribute("db.pool.in_use", pool.get_stats().get("pool_size", 0)
                                              - pool.get_stats().get("pool_available", 0))
    try:
        return fn(conn)
    finally:
        conn_cm.__exit__(None, None, None)

Step 5 — Give transactions and bulk operations their own spans. A transaction holds locks for its whole duration, and statement spans show only the time statements ran. A span around the transaction reveals the time between statements, which is often application work performed while holding locks. Server-side cursors and COPY operations stream data over many round trips; a single span around the whole operation measures what the caller actually waited for.

with tracer.start_as_current_span("place order transaction"):
    with pool.connection() as conn, conn.transaction():
        conn.execute("INSERT INTO orders (id, total) VALUES (%s, %s)", (oid, total))
        conn.execute("UPDATE stock SET qty = qty - %s WHERE sku = %s", (qty, sku))

Expected Output: the transaction and its statements, with row counts.

place order transaction   INTERNAL  38 ms
  INSERT orders           CLIENT     6 ms   db.response.returned_rows=1
  UPDATE stock            CLIENT     9 ms   db.response.returned_rows=1

Async psycopg

psycopg's async connections — AsyncConnection and the async pool — are covered by the same instrumentation, and spans are parented to whichever task awaited the statement. Two details differ from the synchronous case.

The first is concurrency on a single connection. PostgreSQL processes one statement at a time per connection, so concurrent coroutines sharing one connection serialise at the driver. Their spans overlap in the trace — each started when its coroutine awaited — but the later ones include time waiting behind the earlier ones. A fan-out that looks concurrent in the code and shows staggered statement completion in the trace is usually sharing a connection. Using a pool, with one connection per concurrent operation, restores real concurrency.

The second is pool waiting. The async pool suspends a coroutine rather than blocking a thread when no connection is available, which is cheaper and less visible. The acquisition span from step 4, written with async with, applies unchanged and is the only direct evidence of the wait.

Using the join during an incident

SQL commenting pays for itself the first time a slow query is investigated from both sides, and the investigation has a consistent shape.

Start from the application. A slow request's trace shows a database span of, say, nine hundred milliseconds. The statement template and row count are on the span; the trace identifier is on the span. Searching PostgreSQL's slow query log for that trace identifier returns the server's own record of the same execution: its actual execution time, the rows it examined, whether it waited on a lock and for how long. If the server says nine hundred milliseconds of execution, the query itself is slow, and the next step is its plan. If the server says forty milliseconds, the other eight hundred and sixty were spent outside the database — acquiring a connection, on the network, or in psycopg converting a large result — and no amount of index work will help.

Start from the database. A database administrator sees a statement consuming a large share of total execution time in the statistics extension, or a long lock wait in the logs. The comment on the statement carries a trace identifier, which leads to a specific trace, which names the service, the endpoint and — through manual spans — the business operation that issued the statement. A conversation that used to begin with "which service sends this query" begins instead with the code.

The join also resolves an old argument. Application teams see slow spans and suspect the database; database teams see healthy server metrics and suspect the application. With both views of the same execution side by side, the difference between client duration and server execution is a number, and the argument ends.

Server-side cursors and COPY

Two psycopg features produce spans that are easy to misread, because the work they represent does not map to one round trip.

A named, server-side cursor fetches results in batches over many round trips. The instrumentation records the initial statement as one span, and subsequent fetches may appear as further spans or not at all depending on how they are issued. The time a caller spends iterating over a large result is spread across those fetches and the application's own processing between them. A span around the whole iteration — opened before the cursor, closed after the last row — measures what the caller actually waited for.

COPY operations stream data in or out and can run for minutes on large tables. The initial command produces a span, and the streaming that follows is part of the same operation from the caller's perspective. Wrapping the whole copy in a span, with the byte or row count as an attribute, gives a single measurement for what is logically a single operation, which is what an investigation into a slow export or import needs.

Configuration options

Verification

Issue a query inside a span and confirm the client span's trace identifier appears in PostgreSQL's view of the statement.

with tracer.start_as_current_span("verify") as span:
    with pool.connection() as conn:
        conn.execute("SELECT pg_sleep(2)")      # long enough to see in pg_stat_activity
print(f"{span.get_span_context().trace_id:032x}")

Expected Output: the same identifier in both places.

9f2a71c4f0b84c2e9d5f1a7b3c8e6d02

Common mistakes

Instrumenting after the pool is created. Error signature: no database spans for pooled connections. Root cause: connections opened before wrapping. Remediation: call the instrumentor first.

Commenting enabled without checking tooling. Error signature: a statistics dashboard showing thousands of distinct statements. Root cause: a tool that does not strip comments when grouping. Remediation: confirm how your tooling normalises before enabling everywhere.

No row counts. Error signature: indexing work on a query whose real problem is returning too much. Root cause: duration alone cannot distinguish the two. Remediation: record rows on every span.

Transactions without spans. Error signature: lock waits with no slow statements anywhere. Root cause: time between statements invisible. Remediation: a span around each transaction.

Concurrent coroutines on one connection. Error signature: a fan-out whose statements complete one after another. Root cause: a shared async connection serialising statements. Remediation: one pooled connection per concurrent operation.

Frequently Asked Questions