Python Observability

Tracing Redis Calls in Python

Redis is fast enough that a single request may issue dozens or hundreds of commands, and a span per command is trivially cheap to produce and easy to overdo. This page covers instrumenting redis-py, keeping keys — which usually embed identifiers — out of span attributes, tracing pipelines as the single round trip they are, and deciding when cache behaviour is better described by metrics than by spans. It is a task article under tracing databases and message queues, part of the distributed tracing and OpenTelemetry in Python section.

When the cache spans bury the trace A request that renders a product listing reads fifty product records from Redis one at a time, each with a GET, plus fifty price entries. The trace contains a hundred sub-millisecond Redis spans, each carrying a full key such as product 8812 as an attribute, and the one slow database query that actually made the request slow is hard to find among them. The same request rewritten to fetch all hundred keys in one pipeline produces a single Redis span of two milliseconds with a command count attribute and a key prefix attribute, and the slow database query stands out immediately. The note records that the rewrite also made the request faster, because a hundred round trips became one. a listing page reading 100 cache keys one GET per key GET /products … 100 spans, each key an attribute the slow SELECT — hard to spot one pipeline, prefix attribute GET /products pipeline · 100 commands · prefix product the slow SELECT — obvious fewer spans, a readable trace — and a faster request, because 100 round trips became one
A span per cache read hides the span that matters. Batching the reads fixes the trace and the latency at the same time.

Prerequisites

pip install "redis>=5.0.0,<6.0.0" \
            "opentelemetry-instrumentation-redis>=0.48b0,<1.0.0" \
            "opentelemetry-sdk>=1.27.0,<2.0.0" \
            "prometheus-client>=0.20.0,<1.0.0"

Implementation

Step 1 — Enable the instrumentation at startup. The instrumentor wraps redis-py's command execution for both the synchronous and asyncio clients. Every command produces a client span with the database system and the command name.

from opentelemetry.instrumentation.redis import RedisInstrumentor

RedisInstrumentor().instrument(request_hook=redis_request_hook)

Step 2 — Record the key prefix, not the key. Keys in most applications follow a type:identifier pattern — cart:u_8f21c9, product:8812, session:…. The full key as an attribute is unbounded in cardinality and may contain personal identifiers. A request hook that extracts the part before the first separator gives a bounded attribute that still says what kind of data was touched.

def redis_request_hook(span, instance, args, kwargs):
    if not span.is_recording() or len(args) < 2:
        return
    key = args[1]
    if isinstance(key, bytes):
        key = key.decode(errors="replace")
    if isinstance(key, str):
        span.set_attribute("app.cache.key_prefix", key.split(":", 1)[0])
        span.set_attribute("db.statement", args[0])   # the command name only

Step 3 — Treat pipelines as one operation. A pipeline sends many commands in one round trip, and the instrumentation records it as one span with the commands listed. That is the right model: on the wire it is one operation, and its duration is one round trip plus server processing. Rewriting loops of individual commands as pipelines improves both the trace and the latency.

def load_products(r, ids):
    pipe = r.pipeline(transaction=False)
    for pid in ids:
        pipe.get(f"product:{pid}")
    return pipe.execute()                   # one span, one round trip

Expected Output: a single span for the whole batch.

PIPELINE  CLIENT  2.1 ms  db.redis.pipeline_length=100  app.cache.key_prefix=product

Step 4 — Decide which commands deserve spans. Reads that happen hundreds of times per request, each in well under a millisecond, contribute little to a trace and a great deal to its size — and to the export volume, which is billed per span in many backends. Options range from sampling them within the trace to disabling cache instrumentation entirely and relying on metrics. Writes, slow commands and anything with side effects — EVAL, DEL, list operations used as queues — usually deserve spans.

Step 5 — Measure hit rate with metrics. Hit rate is the single most important number about a cache, and spans are the wrong place to compute it. Spans are sampled, and tail sampling in particular keeps slow and failing traces preferentially, so a hit rate computed from stored spans is biased. A counter of hits and misses labelled by key prefix — bounded — gives an exact rate from every request.

from prometheus_client import Counter, Histogram

CACHE = Counter("cache_requests_total", "Cache lookups", ["prefix", "result"])
CACHE_LATENCY = Histogram("cache_request_seconds", "Cache latency", ["prefix"],
                          buckets=(0.0001, 0.00025, 0.0005, 0.001, 0.0025, 0.005, 0.01))

def cached_get(r, key):
    prefix = key.split(":", 1)[0]
    with CACHE_LATENCY.labels(prefix).time():
        value = r.get(key)
    CACHE.labels(prefix, "hit" if value is not None else "miss").inc()
    return value
Why hit rate belongs in a metric The true cache hit rate over an hour is ninety-four percent, measured by a counter incremented on every lookup. Computed from stored spans, the same hit rate comes out at seventy-one percent, because the tail sampler keeps slow traces preferentially and cache misses make requests slower, so traces containing misses are over-represented among those stored. The note records that any rate computed from a sampled trace store is biased in the direction of whatever the sampler favours, and that metrics, counted before any sampling, are the right source for rates. the same hour, the hit rate computed two ways metric, every lookup 94% hits from sampled spans 71% hits — biased tail sampling keeps slow traces, and misses make requests slow so traces containing misses are over-represented in the store rates come from metrics counted before sampling; spans explain individual requests
A sampled trace store over-represents whatever the sampler favours. Rates belong to metrics, which count every event before any sampling happens.

Redis as a queue or lock

Redis is used for more than caching, and the other uses need different treatment.

As a queue. List operations — LPUSH and BRPOP — or streams used to pass work between services are messaging, not caching. The producer and consumer should propagate trace context just as with any broker: inject into the message payload, since Redis list entries have no header field, and extract on the consumer side. The consumer's span then relates to the producer's, and the queue wait — the time between push and pop — becomes visible as an attribute. The general patterns are in tracing databases and message queues.

As a lock. A distributed lock acquired with SET NX and a timeout, or a library built on it, can be the reason a request is slow — it waited for a lock held elsewhere. The acquisition should be its own span, with the wait time and whether it succeeded, because the individual commands are fast and the waiting happens in the retry loop around them. Without that span, lock contention appears as unexplained gaps between fast Redis commands.

As a rate limiter. A rate-limiting check typically runs on every request and is very fast. It is a candidate for no span at all, with a metric counting allowed and rejected requests, and an attribute on the server span recording the rejection when one happens.

The common thread is that the command-level spans the instrumentation produces are correct and often not the useful unit. The useful unit is the operation the commands implement — enqueue, acquire lock, check limit — and that deserves a manual span with attributes describing its outcome.

Reading Redis latency correctly

Redis spans are short, and interpreting them has a few pitfalls that longer database spans do not.

Client time dominates. A Redis command typically executes on the server in microseconds. A client span of two milliseconds is almost entirely network round trip, connection acquisition and serialisation. When Redis spans grow, the cause is rarely Redis itself; it is more often the network path, a saturated connection pool, or the event loop being too busy to process the response promptly. Comparing Redis spans with the server's own slow log — which records commands exceeding a threshold on the server side — separates the two quickly.

Large values are expensive on the client. A GET returning a two-megabyte serialised object is fast on the server and slow on the client, which must receive and deserialise it. A span that records the response size as an attribute makes this visible, and the fix — storing smaller values, or fetching only the fields needed with a hash — is a data-modelling change rather than a Redis one.

Blocking commands are supposed to be slow. BRPOP, BLPOP and XREAD with a block timeout wait for data by design. Their spans measure the wait, which may be seconds, and including them in a latency aggregate makes the aggregate meaningless. Excluding blocking commands from latency views, or instrumenting the consumer loop so the wait is recorded as queue idle time rather than as operation latency, keeps the numbers honest.

Cluster redirects add round trips. In a clustered deployment, a command sent to the wrong node is redirected, doubling its round trips. Spans that are consistently twice as long as their peers for certain key prefixes often indicate a client whose slot map is stale. The instrumentation records the host each command was sent to, which is enough to spot it.

Spans per request with and without a cache span policy A bar chart of spans in one request trace for a page that reads many cached values. Without any policy, every Redis GET gets a span: 212 spans, with the database and HTTP spans buried among them. Recording only pipeline and MGET calls as spans, and single GETs as a counter, gives 34 spans. Suppressing Redis spans entirely and recording hit and miss counts as metrics gives 9 spans, with cache behaviour visible on the dashboard instead. The note says cache calls are usually better as metrics than as spans, unless a specific slow call is being investigated. spans in one page-render trace every GET as a span 212 spans pipelines and MGET only 34 spans Redis as metrics only 9 spans cache calls usually belong in metrics, not spans turn per-call spans back on while investigating a specific slow path
A span per cache read can bury the spans that matter. Hit and miss counters show cache behaviour without the noise.

Configuration options

Concern Recommendation Why
Instrumentation RedisInstrumentor at startup sync and asyncio clients
Keys prefix only, via request hook bounded, no identifiers
Pipelines one span, command count matches the round trip
High-volume reads sample, filter, or drop readable traces
Hit rate metric by prefix exact, unbiased
Queue usage propagate context in the payload consumer relates to producer
Lock usage manual span around acquisition contention made visible

Verification

Check that no span carries a full key.

keys = [s.attributes.get("app.cache.key_prefix") for s in exporter.get_finished_spans()
        if s.attributes.get("db.system") == "redis"]
assert all(k and ":" not in k for k in keys), keys
print(sorted(set(keys)))

Expected Output: a short, bounded list of prefixes.

['cart', 'price', 'product', 'session']

Common mistakes

Full keys as span attributes. Error signature: an attribute with millions of distinct values, some containing user identifiers. Root cause: default recording of arguments. Remediation: prefix only, via a request hook.

A loop of individual GETs. Error signature: traces dominated by hundreds of tiny Redis spans, and slow pages. Root cause: one round trip per key. Remediation: a pipeline or MGET.

Hit rate from spans. Error signature: a hit rate far lower than the application's own experience suggests. Root cause: sampling bias. Remediation: a metric counted on every lookup.

No span around lock acquisition. Error signature: gaps between fast commands during contention. Root cause: the waiting happens in the retry loop. Remediation: a manual span with wait time and outcome.

Blocking commands in latency views. Error signature: a Redis p99 of several seconds for a healthy cache. Root cause: BRPOP or XREAD waits counted as operation latency. Remediation: exclude blocking commands from latency aggregates.

Redis queues without propagation. Error signature: consumer traces unrelated to the requests that enqueued work. Root cause: no header field and no context in the payload. Remediation: inject into the payload, extract on pop.

Frequently Asked Questions

Does redis-py instrumentation record keys?

It records the command and, depending on version and configuration, its arguments, which include the key. Keys often embed identifiers, so recording them verbatim creates an unbounded attribute and may expose data. A request hook that records only the prefix is the usual remedy.

How are pipelines traced?

As a single span covering the whole pipeline execution, with the commands it contained recorded as an attribute. That matches how the pipeline behaves on the wire — one round trip — and is usually what an investigation needs.

Should every cache GET be a span?

Not necessarily. A request that performs two hundred cache reads produces two hundred sub-millisecond spans that bury the ones that matter. Metrics describe cache behaviour — hit rate, latency by prefix — more cheaply and more accurately.

Is the async Redis client traced too?

Yes. The instrumentation covers the asyncio client in redis-py, and spans are parented to the task that awaited the command.

Related Guides