Tracing Databases and Message Queues in Python

Most of a typical Python request's time is spent waiting on something outside the process — a database, a cache, a broker — and the spans for those calls are the ones that most often explain a slow trace. Automatic instrumentation covers the common client libraries well; the work that remains is sanitising what gets recorded, adding the attributes that make spans queryable, carrying trace context through a broker, and deciding how consumer spans relate to producers. This guide covers the principles, and its child pages cover tracing PostgreSQL queries with psycopg, tracing Redis calls in Python and tracing Kafka producers and consumers in Python. It is part of the distributed tracing and OpenTelemetry in Python section.

Prerequisites

pip install "opentelemetry-instrumentation-psycopg>=0.48b0,<1.0.0" \
            "opentelemetry-instrumentation-redis>=0.48b0,<1.0.0" \
            "opentelemetry-instrumentation-confluent-kafka>=0.48b0,<1.0.0" \
            "opentelemetry-sdk>=1.27.0,<2.0.0"

Concept and architecture

Every call a service makes to a database, cache or broker is a client span — or, for publishing, a producer span — with the same basic shape: the system, the operation, the target, and how long it took. What varies between libraries is how much detail the instrumentation records and how safe that detail is.

Databases get a span per statement, carrying the database system, the operation, the target table and the statement text. The statement is the most useful attribute and the most dangerous: with placeholders it is a template that groups well and contains no data; with values interpolated it is a unique string per execution containing whatever the query was filtering on. Tracing slow SQL queries in Python covers making statement spans groupable and ranking them.

Caches get a span per command. The command is useful; the full key often is not, because keys typically embed identifiers — cart:u_8f21c9 — which makes the attribute unbounded and may expose data. Recording the key's prefix or pattern rather than the full key keeps the span useful and safe.

Brokers get a producer span per publish and a consumer span per message processed, and the relationship between them is the interesting part. The producer instrumentation injects trace context into message headers; the consumer instrumentation extracts it. With that in place, the consumer's work — including its own database calls — can be related back to the request that published the message, which is often the only way to explain why a downstream effect happened.

The relationship itself is a design decision. A consumer span as a child of the producer span makes one trace cover the whole path, and that trace's duration includes however long the message sat in the queue — seconds or hours. A consumer span as a new root with a link to the producer keeps each trace's duration meaningful, at the cost of navigating between two traces. Adding span links for batch work discusses the trade in detail.

Step-by-step implementation

Step 1 — Enable instrumentation for every client library. Each driver or client has its own package. Enabling them at startup, before connections are created, means every call is traced.

from opentelemetry.instrumentation.psycopg import PsycopgInstrumentor
from opentelemetry.instrumentation.redis import RedisInstrumentor
from opentelemetry.instrumentation.confluent_kafka import ConfluentKafkaInstrumentor

PsycopgInstrumentor().instrument(enable_commenter=True)
RedisInstrumentor().instrument()
kafka = ConfluentKafkaInstrumentor()
producer = kafka.instrument_producer(Producer(conf))
consumer = kafka.instrument_consumer(Consumer(conf))

Step 2 — Verify statements are sanitised. Before trusting the spans — and certainly before shipping them to a store that more people can read than can read the database — inspect one: the statement should contain placeholders, not values. If it contains values, the driver or ORM is interpolating before execution, and the fix is at the query layer — parameterised queries — rather than in the instrumentation.

Step 3 — Bound cache key attributes. A request hook on the cache instrumentation can replace the full key with its prefix before the span is recorded, keeping the attribute's cardinality small and its content free of identifiers.

def redis_request_hook(span, instance, args, kwargs):
    if span.is_recording() and len(args) > 1 and isinstance(args[1], (str, bytes)):
        key = args[1].decode() if isinstance(args[1], bytes) else args[1]
        span.set_attribute("app.cache.key_prefix", key.split(":", 1)[0])

RedisInstrumentor().instrument(request_hook=redis_request_hook)

Step 4 — Add the attributes that queries depend on. Rows affected by a write, items returned by a read, the message size for a publish, the partition a message went to. These turn a span from "a call happened" into "a call happened and did this much work", which is what distinguishes a slow query that returned a million rows from one that returned one.

Step 5 — Propagate context through the broker and verify it. The producer and consumer instrumentations handle injection and extraction, provided both are enabled and nothing between them strips headers. A test that publishes and consumes through a local broker, and asserts that the consumer span relates to the producer span, confirms the path.

Step 6 — Apply one consumer convention across the fleet. Child or link, applied consistently and written down where every team will find it. Mixed conventions make cross-service traces unpredictable: some consumers appear inside the producer's trace, others in their own, and nobody can predict which without checking.

Configuration reference

Async and concurrency considerations

Async drivers — asyncpg, redis's asyncio client, aiokafka — produce spans the same way, with one extra consideration: many concurrent operations share one event loop, and the span context for each comes from the task that issued it. As long as each operation is awaited within the request's task, or in a task spawned from it, spans are parented correctly. Operations issued from callbacks registered on long-lived connection objects — reconnection handlers, pool maintenance — run in whatever context was current when the callback was registered and should not be expected to belong to any request.

Connection pools affect span timing in a way worth knowing. A client span measures from the moment the instrumented call begins, which may include time waiting for a pooled connection before the operation reaches the server. Under pool exhaustion, database spans grow long while the database itself reports fast queries. Separating acquisition time from execution time, as in observing connection pool exhaustion, makes the difference visible.

For consumers, concurrency determines span structure. A consumer processing messages one at a time produces one consumer span per message. A consumer that pulls a batch and processes items concurrently should create a span per message inside the batch, each related to its own producer, or a batch span with links — never a single span parented to one arbitrary message.

Production code examples

A consumer loop that extracts context, relates the consumer span to the producer by link, and records the queue wait:

import time
from opentelemetry import trace, context
from opentelemetry.propagate import extract
from opentelemetry.trace import Link, SpanKind

tracer = trace.get_tracer("fulfilment")

def handle(msg) -> None:
    headers = {k: v.decode() for k, v in (msg.headers() or [])}
    producer_ctx = trace.get_current_span(extract(headers)).get_span_context()
    links = [Link(producer_ctx)] if producer_ctx.is_valid else []

    with tracer.start_as_current_span(
        f"process {msg.topic()}",
        kind=SpanKind.CONSUMER,
        context=context.Context(),                   # new root for this trace
        links=links,
    ) as span:
        span.set_attribute("messaging.system", "kafka")
        span.set_attribute("messaging.destination.name", msg.topic())
        span.set_attribute("messaging.kafka.message.offset", msg.offset())
        _, ts_ms = msg.timestamp()
        span.set_attribute("app.queue_wait_ms", max(0, int(time.time() * 1000) - ts_ms))
        fulfil(msg.value())

Expected Output: a consumer trace that records how long the message waited and links back to the request that sent it.

process order-events   CONSUMER  204 ms  app.queue_wait_ms=40112  links=1
  SELECT inventory     CLIENT     31 ms
  UPDATE shipments     CLIENT     18 ms

Reading dependency spans during an incident

Dependency spans are where an incident investigation usually spends most of its time, and a few reading habits make them quicker to interpret.

Compare the span with the server's own view. A database span of eight hundred milliseconds says the client waited that long. It does not say the database took that long. The difference — network, connection acquisition, client-side result processing — is often the whole story. SQL commenting, which puts the trace context into the statement, lets the span be matched to the database's own record of the same execution, which states how long the server spent. If the server says four milliseconds, the problem is on the client side of the connection.

Look at the distribution across the same statement, not one span. One slow execution of a normally fast statement points to lock contention or a cold cache at that moment; every execution being slow points to the statement or its plan. Grouping spans by statement template and comparing percentiles across the incident window separates the two.

Look at what surrounds the slow span. A slow database span preceded by a gap may be waiting on a pool; one followed by a gap may have returned a large result that the application then processed slowly. The spans before and after, and the gaps between them, often explain more than the slow span itself.

For consumers, check the queue wait first. A consumer trace that looks fast may belong to a message that waited an hour. The queue wait attribute from the example above — or the difference between the message timestamp and the consumer span's start — is frequently the latency a user actually experienced, and it is invisible in the consumer's own span duration.

Check the other side of the broker. When a consumer span is missing its relationship to a producer, the producer's span often still exists, and finding it by time and topic reconstructs the path manually. The pattern of which relationships are missing — all messages from one producer, or all messages through one bridge — usually identifies where headers are being lost.

Semantic conventions for data systems

The semantic conventions define attribute names for databases and messaging, and following them has the same benefit as for HTTP: every service's spans can be queried the same way, and backends render them with purpose-built views.

For databases, the core attributes are the system, the operation, the collection or table, and the query text — with the text sanitised. For messaging, they are the system, the operation (publish, receive, process), the destination name, and message identifiers where useful. Server address and port apply to both and identify which instance a client talked to, which matters for sharded or replicated stores.

Automatic instrumentation sets these, and manual spans for custom data access — a repository layer wrapping several calls, a bespoke client for an internal store — should use the same names. A manual span named load customer aggregate with db.system and db.collection.name set sits naturally alongside the driver's spans beneath it, and a query for all database activity against a collection finds both. The naming principles are the same as in naming spans and using semantic conventions.

Retries and transactions

Two behaviours of data clients complicate their spans and are worth handling deliberately.

Retries inside the client. Some drivers and most broker clients retry transient failures internally. Whether each attempt gets its own span depends on where the instrumentation hooks in: at the public API, one span covers every attempt and its duration includes the retries; at the protocol level, each attempt is visible. The first hides flapping, where a dependency fails and succeeds alternately; the second shows it. Where the instrumentation only offers the first, recording the attempt count as an attribute — from the client's own retry callback, if it has one — restores most of the information.

Transactions spanning several statements. A transaction is a unit the database sees as one, and the trace shows it as several statement spans. Wrapping the transaction in its own span — transaction or a business name such as place order transaction — makes its total duration visible and groups its statements, which matters because a transaction holds locks for its whole duration, not only while statements run. A transaction span that is much longer than the sum of its statements is holding locks while the application does something else, which is both a latency problem and a contention problem for every other request touching the same rows.

Deciding what to trace

Client instrumentation traces everything by default, and at high call volume that produces traces dominated by dependency spans. A few decisions keep them useful.

Keep database spans. They are the most common explanation for a slow request, and a span per statement is the right granularity for all but the most query-heavy endpoints — and for those, the span count is itself the finding, as detecting N+1 queries with traces explains.

Consider cache spans carefully. A request making two hundred cache reads produces two hundred spans that are each a fraction of a millisecond. Metrics — hit rate and latency by key prefix — describe cache behaviour better than spans do, and disabling cache instrumentation, or keeping only slow calls, often improves traces.

Always keep producer and consumer spans. They are few — usually very few — relative to database calls and they carry the context that joins services. Without them the asynchronous half of the system is invisible.

Record volume on spans rather than creating more spans. Rows returned, items processed, message size — an attribute on the existing span says how much work was done without adding to the span count.

Common mistakes

Values in SQL statement attributes. Error signature: statement attributes with a unique value per execution and data in them. Root cause: interpolated SQL. Remediation: parameterised queries; check a real span.

Full cache keys as attributes. Error signature: an attribute with millions of distinct values, some containing identifiers. Root cause: default recording of the key. Remediation: record the prefix with a request hook.

One side of the broker uninstrumented. Error signature: consumer traces unrelated to any request. Root cause: the producer did not inject, or the consumer did not extract. Remediation: instrument both, and test the path.

Headers stripped in transit. Error signature: instrumented producer and consumer, and still no relationship. Root cause: a proxy, bridge or serialisation step dropping message headers. Remediation: carry context in the message body as a fallback, or fix the intermediary.

Mixed consumer conventions. Error signature: some consumers inside producer traces, others separate, unpredictably. Root cause: no fleet-wide decision. Remediation: choose child or link and apply it everywhere.

A long transaction span nobody looks at. Error signature: lock waits in the database and no obvious slow query. Root cause: a transaction held open across non-database work, visible only as a gap between statement spans. Remediation: a span around each transaction, and an alert when its duration far exceeds its statements'.

Retries hidden inside one span. Error signature: a dependency that looks uniformly slow and is actually failing and recovering. Root cause: client-internal retries under one span. Remediation: record the attempt count, or instrument at the attempt level.

Cache spans drowning the trace. Error signature: traces with hundreds of sub-millisecond spans and the useful ones buried. Root cause: default instrumentation at high call volume. Remediation: disable or filter cache spans and use metrics for cache behaviour.

Frequently Asked Questions