Instrumenting Databases and Cache Clients

Problem Framing

The trace waterfall shows a 900 ms POST /checkout span with a single 870 ms child called internal_work, and nothing else. Everyone agrees the database is probably the problem, but the trace cannot say which query, how many times it ran, or whether the time went into executing SQL or waiting for a free connection. The database’s own slow-query log shows nothing over 40 ms, which means the time is going somewhere the database never sees.

Database and cache calls are where most request latency actually lives, and they are the easiest thing to instrument badly. Wrap the ORM and you get one span per business method with no visibility into the twelve queries it issued. Wrap the driver and you get precise per-statement timing — plus, if you are careless, a copy of every value your users ever typed, permanently stored in trace storage.

This page covers the instrumentation layer to hook, the db.* attributes that make the resulting spans useful, how to separate pool wait from query time, and how to instrument cache clients without drowning the exporter in spans.

Prerequisites

• A working OpenTelemetry SDK setup with an exporter you can read output from.
• The driver-specific instrumentation package for your stack (opentelemetry-instrumentation-psycopg2, @opentelemetry/instrumentation-pg, opentelemetry-javaagent with the JDBC module, and so on).
• Familiarity with the span attributes and semantic conventions — the db.* keys are what turn these spans into dashboards.
• A Collector in the path if you plan to redact or sample data-layer spans centrally.

Concept Deep-Dive: Which Layer to Hook

Every stack offers three places to create the span, and they produce very different traces. The layer you hook determines what questions the trace can answer.

The ORM layer is the wrong place for the primary span. An ORM call is a business operation, not a database operation, and one span for load_with_items() hides the N+1 pattern that is usually the actual bug. ORM-level spans are useful as parents, not as the only span.

The driver layer is correct. Every mainstream driver exposes a hook — psycopg2’s execute wrapper, pg’s query events, JDBC’s statement interceptor, node-redis’s command middleware — and the language auto-instrumentation packages already use them. One span per statement is what makes N+1 query detection possible.

The pool layer is the missing piece nearly everyone skips. When a connection pool is saturated, the driver span starts after a connection is available, so the queue wait vanishes from the trace and the query looks fast while the endpoint is slow. Recording acquisition separately turns an unexplained gap in the waterfall into a labelled span.

The attributes that matter on a data-layer span

Step-by-Step Implementation

Step 1 — Patch the driver before the pool is created

Auto-instrumentation works by monkey-patching the driver module. If your connection pool is constructed at import time, before the SDK initializes, the pool holds references to unpatched functions and emits nothing — the single most common reason database spans are missing entirely.

# main.py — order matters: instrument first, THEN import anything that opens a pool.
from opentelemetry.instrumentation.psycopg2 import Psycopg2Instrumentor
from opentelemetry.instrumentation.redis import RedisInstrumentor

# enable_commenter injects the trace id into the SQL as a comment, so the
# database's own slow-query log can be joined back to the trace.
Psycopg2Instrumentor().instrument(enable_commenter=True, commenter_options={
    "db_driver": True, "opentelemetry_values": True,
})
RedisInstrumentor().instrument()

# Only now import the modules that build connection pools.
from app.db import pool          # noqa: E402
from app.cache import redis_client   # noqa: E402

enable_commenter is worth turning on deliberately: it appends /*traceparent='00-<trace-id>-...'*/ to each statement, which means a DBA looking at pg_stat_activity can paste the trace ID into the trace UI and see the request that issued the query. The cost is a slightly longer statement and a cache-plan consideration on some engines.

Step 2 — Apply the conventions on the span

If you hand-instrument — a custom driver, a proprietary store, a raw socket protocol — set the same attributes the auto-instrumentation would.

// Node.js — hand-instrumented data-layer call with the db.* convention
const { trace, SpanKind, SpanStatusCode } = require('@opentelemetry/api');
const tracer = trace.getTracer('app.db');

async function findOrdersByTenant(tenantId, limit) {
  // Span name convention: "<operation> <target>" — low cardinality, never the full SQL.
  return tracer.startActiveSpan('SELECT orders', { kind: SpanKind.CLIENT }, async (span) => {
    span.setAttribute('db.system.name', 'postgresql');
    span.setAttribute('db.namespace', 'orders_prod');
    span.setAttribute('db.collection.name', 'orders');
    span.setAttribute('db.operation.name', 'SELECT');
    // Parameterized text only — $1 stays a placeholder, never the tenant value.
    span.setAttribute('db.query.text',
      'SELECT id, total FROM orders WHERE tenant_id = $1 ORDER BY created_at DESC LIMIT $2');
    span.setAttribute('server.address', process.env.PGHOST);
    span.setAttribute('server.port', 5432);
    try {
      const res = await pool.query(
        'SELECT id, total FROM orders WHERE tenant_id = $1 ORDER BY created_at DESC LIMIT $2',
        [tenantId, limit],
      );
      // Row count exposes "fetched 50k rows to render 20" without reading the query.
      span.setAttribute('db.response.returned_rows', res.rowCount);
      return res.rows;
    } catch (err) {
      span.setAttribute('error.type', err.code || 'db_error');
      span.setStatus({ code: SpanStatusCode.ERROR, message: err.message });
      throw err;
    } finally {
      span.end();
    }
  });
}

Step 3 — Make connection-pool wait time visible

Acquisition is a separate concern from execution, and conflating them makes a capacity problem look like a query problem.

# db.py — wrap acquisition in its own span so queue wait is attributable
from opentelemetry import trace
from contextlib import contextmanager

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

@contextmanager
def acquire_connection(pool):
    # This span covers ONLY the wait for a free connection.
    with tracer.start_as_current_span("db.pool.acquire") as span:
        span.set_attribute("db.client.connection.pool.name", "orders_pool")
        span.set_attribute("db.client.connection.pool.size", pool.maxconn)
        span.set_attribute("db.client.connection.pool.idle", pool.idle_count())
        conn = pool.getconn()          # blocks here when the pool is exhausted
        # A pool with zero idle connections at acquisition time is the signal that
        # queue wait, not query time, is your latency source.
        span.set_attribute("db.pool.wait_was_blocking", pool.idle_count() == 0)
    try:
        yield conn
    finally:
        pool.putconn(conn)

Step 4 — Instrument the cache and record hit or miss

Cache spans answer a different question from database spans: not “how long did it take” but “did it work”. A cache that is fast and always missing is worse than no cache.

# cache.py — hit/miss as a bounded attribute, safe to promote into metrics
from opentelemetry import trace

tracer = trace.get_tracer("app.cache")

def get_product(product_id: str):
    with tracer.start_as_current_span("GET product") as span:
        span.set_attribute("db.system.name", "redis")
        span.set_attribute("db.operation.name", "GET")
        # Key TEMPLATE, not the key itself — "product:{id}" is bounded, the
        # literal key is one distinct value per product.
        span.set_attribute("cache.key.template", "product:{id}")
        raw = redis_client.get(f"product:{product_id}")
        hit = raw is not None
        span.set_attribute("cache.hit", hit)
        if not hit:
            # The miss path is where the latency actually is; keep it inside the
            # same trace so the waterfall shows cache miss → database read.
            span.set_attribute("cache.miss.reason", "absent")
            product = load_product_from_db(product_id)
            redis_client.setex(f"product:{product_id}", 300, serialize(product))
            return product
        return deserialize(raw)

Step 5 — Sanitize, then verify nothing leaks

Sanitization belongs in two places: the client, which should never build an interpolated statement in the first place, and the Collector, which is the backstop for the library you forgot about.

# collector-config.yaml — belt and braces for data-layer spans
processors:
  transform/db_sanitize:
    error_mode: ignore
    trace_statements:
      - context: span
        statements:
          # Numeric literals that slipped past a driver's own sanitizer.
          - replace_pattern(attributes["db.query.text"], "\\b\\d{3,}\\b", "?")
              where attributes["db.query.text"] != nil
          # Quoted string literals — the classic PII carrier in a WHERE clause.
          - replace_pattern(attributes["db.query.text"], "'[^']*'", "'?'")
              where attributes["db.query.text"] != nil
          # Cap statement length so an ORM-generated monster cannot dominate storage.
          - set(attributes["db.query.text"],
                Substring(attributes["db.query.text"], 0, 2048))
              where Len(attributes["db.query.text"]) > 2048

The path a value takes from your application to trace storage — and the two points where it can be stopped — looks like this:

Verification

Issue one request and read the spans it produced:

# Count spans by name for a single trace id, straight from the debug exporter
grep -A2 '"trace_id": "4bf92f' /var/log/app/otel.jsonl \
  | grep '"name"' | sort | uniq -c | sort -rn

#   20 "name": "SELECT sku"        ← N+1: twenty identical statements
#    1 "name": "SELECT orders"
#    1 "name": "db.pool.acquire"
#    1 "name": "GET product"

Three checks tell you the instrumentation is correct:

• Every data-layer span has a parent. An orphaned SELECT means the query ran outside the active context — see debugging orphaned spans in async workflows.
• db.query.text contains placeholders, never values. Grep the exporter output for a known test value (grep '[email protected]') and expect zero hits.
• Span count per request is what you expect. Twenty identical statements in one request is the finding, not a measurement error.

Edge Cases and Gotchas

1. Prepared statements report the prepare, not the execute. Some drivers create the span on prepare() and reuse it, so repeated executions of a cached statement disappear. Check whether your driver’s instrumentation hooks execute separately.
2. Lazy result sets end the span too early. A cursor that streams rows finishes its span when the query returns, not when rows are consumed, so the trace under-reports the true cost. Wrap the iteration if row fetching is significant.
3. Read replicas look identical without server.address. Two spans at the same latency against different hosts are indistinguishable unless the peer is recorded, which makes replica lag invisible.
4. Transaction spans need explicit boundaries. BEGIN and COMMIT are separate statements; without a wrapping span, the time a transaction holds locks between them is not attributable to anything.
5. Cache clients can outnumber every other span type combined. A service issuing 40 Redis calls per request at 500 RPS produces 20,000 cache spans per second, dwarfing everything else. Consider a dedicated sampler or aggregating per-request cache work under one span with a count attribute.
6. Connection-pool metrics beat pool spans at high volume. If acquisition is almost always instant, the acquire span is pure overhead. Emit it only when the wait exceeds a threshold, or fall back to db.client.connection.* metrics.

Performance and Scale Notes

Span volume is the real cost. A span costs roughly 1–3 µs to create and ~200–400 bytes to export. At 40 data-layer spans per request the CPU cost stays under 1% but export bandwidth becomes the constraint, and the batch processor’s queue is what fills first.

Statement text dominates payload size. A 2 KB ORM-generated SELECT is ten times the size of the rest of the span. Truncating to 512–1024 characters usually preserves the grouping value while cutting export volume substantially.

The chart below shows where the spans actually come from in a typical checkout service — and why the cache client, not the database, is what breaks the exporter.

Sampling interacts badly with data-layer spans. With head-based sampling the whole trace is kept or dropped together, so database spans survive with their parent. With tail-based sampling the Collector must buffer every one of those forty spans until the decision is made, which is why data-heavy services drive tail-sampling memory requirements.

Row counts are cheap and high-value. db.response.returned_rows costs 8 bytes and routinely finds the query that fetches 50,000 rows to display 20 — a class of bug that latency alone never reveals.

Troubleshooting FAQ

Why do my database spans have no parent?

The query is running outside the active context: a thread-pool executor, a background refresh, or a connection created before the SDK initialized. Capture and reattach context at the boundary (see propagating context across thread pools in Java), and confirm the driver is patched before any pool is built.

Should I put the SQL statement on the span?

Yes, parameterized. The template groups identical queries for slow-query analysis and carries no user data. The interpolated statement fails on both counts — see capturing SQL statements without leaking data.

Why does the database span look slower than the database says it is?

The client span covers acquisition, network, execution, and fetch; the database only measures execution. A large gap is almost always pool queue wait or a slow row fetch over the network.

Does instrumenting Redis add meaningful overhead?

CPU-wise, no. Volume-wise, often yes — cache clients are the most common source of span-volume blowouts. Sample them separately or aggregate per-request cache work under a single span.

How do I get cache hit ratio out of traces?

Record cache.hit as a boolean on the cache span and group on it in the backend. Because it has exactly two values it is also safe to promote into span metrics for a permanent dashboard.

Related

• Instrumenting PostgreSQL queries with OpenTelemetry — driver hooks, query comments, and pool spans for psycopg and pg
• Instrumenting Redis clients and cache operations — hit ratio, pipelines, and controlling cache span volume
• Capturing SQL statements without leaking data — sanitization at the driver and in the Collector
• Detecting N+1 queries from trace waterfalls — turning per-statement spans into a repeatable diagnosis
• Auto-instrumentation vs manual span creation — when to accept the library’s spans and when to write your own

↑ Back to SDK Implementation & Context Propagation