Database and I/O Performance Observability in Python

Most of the latency in a typical Python backend is spent waiting for something outside the process — a database, a cache, another service. A profiler correctly reports that the process is idle during those waits, which is true and unhelpful. What is needed instead is instrumentation at the boundaries, precise enough to separate the three failures that account for most database-related slowness: one slow query, too many fast queries, and no connection available to run any query at all. This guide covers all three, plus the outbound HTTP equivalent. It is part of the Python profiling and performance observability section.

Prerequisites

pip install "opentelemetry-sdk>=1.27.0,<2.0.0" \
            "opentelemetry-instrumentation-sqlalchemy>=0.48b0,<1.0.0" \
            "opentelemetry-instrumentation-psycopg>=0.48b0,<1.0.0" \
            "opentelemetry-instrumentation-httpx>=0.48b0,<1.0.0" \
            "prometheus-client>=0.20.0,<1.0.0"

Concept and architecture

Every boundary between a Python process and something it waits for has the same three-part structure, and instrumenting it well means measuring each part separately.

Acquire. Obtaining the resource needed to make the call: a connection from a pool, a slot in a semaphore, a socket from an HTTP client's connection pool. This is usually instant and occasionally dominant, and when it dominates it is because the resource is exhausted.

Execute. The call itself: the query, the request, the cache lookup. This is what most instrumentation measures, and it is what the database or the downstream service would report as its own latency.

Repeat. How many times the call happens per unit of work. A request issuing one query and one issuing three hundred have the same per-query latency and completely different total latency.

The three parts also fail in a characteristic order under load, which is worth knowing because it tells you how close to the edge a service is. Repeat is a constant property of the code and does not change with load. Execute rises gradually as the database gets busier. Acquire stays at zero until the pool is exhausted and then rises almost vertically. A service whose acquisition wait has started to move is therefore much closer to trouble than one whose query latency has.

Automatic instrumentation for database drivers and HTTP clients covers execute well: each query or request becomes a span with its duration and a description. It usually covers acquire poorly or not at all, and it does not aggregate repeat into anything visible — three hundred spans are recorded, but nothing says "three hundred". Filling those two gaps is most of the work in this guide.

The same structure applies to outbound HTTP with one addition: retries. A client configured to retry turns one logical call into several attempts, and a single span covering all of them hides the difference between a slow dependency and a flapping one. Recording each attempt as its own span, which the aiohttp client instrumentation and its HTTP client equivalents can do, makes that visible.

Step-by-step implementation

Step 1 — Instrument the driver so each query is a span. Automatic instrumentation is the right starting point: it covers every query without changing application code, and it records the statement and duration with semantic convention attribute names. The configuration that matters is statement sanitisation, so parameter values never reach a span.

from sqlalchemy import create_engine
from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor

engine = create_engine(DATABASE_URL, pool_size=10, max_overflow=5, pool_timeout=5)
SQLAlchemyInstrumentor().instrument(
    engine=engine,
    enable_commenter=True,          # adds trace context as a SQL comment for DB-side logs
)

Step 2 — Measure connection acquisition as its own span. The pool's checkout is where exhaustion shows up, and it happens before the query span starts. Hooking the pool's events gives a span and a histogram for the wait, which is the only direct measurement of the third failure in the diagram above.

import time
from sqlalchemy import event
from opentelemetry import trace
from prometheus_client import Histogram, Gauge

ACQUIRE = Histogram("db_pool_acquire_seconds", "Wait for a pooled connection", ["pool"],
                    buckets=(0.001, 0.005, 0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5))
IN_USE = Gauge("db_pool_in_use", "Connections checked out", ["pool"])
tracer = trace.get_tracer(__name__)

@event.listens_for(engine, "checkout")
def _checkout(dbapi_conn, record, proxy):
    IN_USE.labels("main").set(engine.pool.checkedout())

@event.listens_for(engine, "checkin")
def _checkin(dbapi_conn, record):
    IN_USE.labels("main").set(engine.pool.checkedout())

def acquire_connection():
    started = time.perf_counter()
    with tracer.start_as_current_span("db.pool.acquire"):
        conn = engine.connect()
    ACQUIRE.labels("main").observe(time.perf_counter() - started)
    return conn

Step 3 — Count queries per request. The number of statements a request issues is the single most useful database metric that nobody records by default. A counter in a context variable, incremented by the driver instrumentation and read at the end of the request, gives it — and a histogram of it per route immediately shows which endpoints issue hundreds.

import contextvars
from prometheus_client import Histogram

_query_count = contextvars.ContextVar("query_count", default=0)
QUERIES_PER_REQUEST = Histogram(
    "db_queries_per_request", "Statements issued per request", ["route"],
    buckets=(1, 2, 5, 10, 20, 50, 100, 200, 500))

@event.listens_for(engine, "before_cursor_execute")
def _count(conn, cursor, statement, parameters, context, executemany):
    _query_count.set(_query_count.get() + 1)

def record_request_queries(route: str):
    QUERIES_PER_REQUEST.labels(route).observe(_query_count.get())
    trace.get_current_span().set_attribute("db.query_count", _query_count.get())

Step 4 — Instrument outbound calls per attempt. For HTTP clients, a span per attempt with the attempt number turns a retrying call from one opaque long span into a visible sequence. Two slow attempts and a fast third is a flapping dependency; one very slow attempt is a slow one.

Step 5 — Bound and sanitise statement text. Statement attributes should be templates with placeholders, truncated to a sensible length. Long generated SQL — bulk inserts, large IN lists — can produce attribute values of many kilobytes, which inflates span size for no diagnostic benefit.

Step 6 — Alert on the three measures, not on query duration alone. A query duration alert catches the first failure. The other two need their own: queries per request above a threshold per route, and acquisition wait above a threshold per pool.

Configuration reference

Async and concurrency considerations

The three-part structure applies unchanged to async drivers, with one significant difference in how acquisition behaves.

An async connection pool makes callers await a connection rather than block a thread, so pool exhaustion does not consume threads — it accumulates awaiting coroutines. That is more efficient and less visible: a threaded service with an exhausted pool shows threads parked in acquisition, while an async one shows a growing number of tasks suspended in the pool's wait, which nothing counts by default. Measuring acquisition time is the same; also counting tasks waiting for a connection makes the async case as legible as the threaded one. Tracing SQLAlchemy async queries covers the async instrumentation specifically.

The query count per request relies on a context variable, which in asyncio is per task. That is exactly right when a request is handled by one task. When a request fans out to several tasks with gather, each child task inherits a copy of the context, and increments in the children are not visible to the parent. Counting correctly across fan-out needs a mutable counter object stored in the context rather than an integer, so every task increments the same object.

For synchronous drivers called from async code — through to_thread or an executor — the connection is acquired and used on a worker thread. The span and the acquisition timing work normally, provided the trace context is carried across into the thread, as described in propagating context across thread and process pools. Without that, the query spans become roots and the request's trace shows none of its database work.

Production code examples

A middleware that records all three measurements per request and attaches them to the server span, so every trace carries its own database summary:

# db_request_metrics.py — per-request database summary on the server span
import contextvars
import time
from dataclasses import dataclass, field

from opentelemetry import trace
from prometheus_client import Histogram


@dataclass
class DbStats:
    queries: int = 0
    query_seconds: float = 0.0
    acquire_seconds: float = 0.0
    statements: dict = field(default_factory=dict)


_stats: contextvars.ContextVar[DbStats | None] = contextvars.ContextVar("db_stats", default=None)

QPR = Histogram("db_queries_per_request", "Statements per request", ["route"],
                buckets=(1, 2, 5, 10, 20, 50, 100, 200, 500))


def begin_request():
    _stats.set(DbStats())                      # a mutable object, shared by child tasks


def on_query(statement_template: str, seconds: float):
    s = _stats.get()
    if s is None:
        return
    s.queries += 1
    s.query_seconds += seconds
    s.statements[statement_template] = s.statements.get(statement_template, 0) + 1


def end_request(route: str):
    s = _stats.get()
    if s is None:
        return
    QPR.labels(route).observe(s.queries)
    span = trace.get_current_span()
    span.set_attribute("db.query_count", s.queries)
    span.set_attribute("db.query_time_ms", round(s.query_seconds * 1000, 1))
    span.set_attribute("db.acquire_time_ms", round(s.acquire_seconds * 1000, 1))
    # 1. The most repeated statement — which is usually the answer for a slow request.
    if s.statements:
        top, count = max(s.statements.items(), key=lambda kv: kv[1])
        span.set_attribute("db.most_repeated_count", count)
        span.set_attribute("db.most_repeated_statement", top[:200])

Expected Output: a server span that answers the database question without opening its children.

{
  "name": "GET /orders/{id}",
  "durationMs": 912,
  "attributes": {
    "db.query_count": 341,
    "db.query_time_ms": 688.4,
    "db.acquire_time_ms": 3.1,
    "db.most_repeated_count": 338,
    "db.most_repeated_statement": "SELECT * FROM line_items WHERE order_id = %s"
  }
}

Three hundred and thirty-eight repetitions of one statement is a loop issuing a query per item, which is the subject of detecting N+1 queries with traces.

Caches deserve the same treatment

A cache is another boundary, and it has the same three parts with one twist: its purpose is to make the execute step disappear, so the most important measurement is how often it succeeds at that.

Hit ratio, per key pattern. A single fleet-wide hit ratio hides everything interesting. A cache with a ninety-five percent overall hit ratio may have one key pattern at ninety-nine percent and another at twelve, and the second is the one worth attention. Recording hits and misses labelled by a bounded key pattern — the prefix, not the key — makes that visible without creating a label per key.

Miss cost. A miss is followed by whatever the cache was protecting against, usually a database query. Measuring the latency of the miss path separately from the hit path shows what the cache is actually worth: a cache whose misses are two milliseconds slower than its hits is providing little, while one whose misses are two hundred milliseconds slower is carrying the service.

Calls per request. Exactly as with the database, a request making hundreds of cache calls is a finding even when each call is fast. The pattern is common in code that fetches related objects one at a time through a cache layer, and it has the same fix as the database version: fetch in bulk.

A cache also introduces a failure that the database alone does not have. When a popular key expires, every concurrent request misses at once and all of them go to the database together. The signature is a periodic spike in database queries and latency with no change in traffic, aligned with a key's expiry time, and it is visible only if cache misses are recorded as a rate over time rather than as a ratio.

What belongs on a dashboard

The measurements in this guide produce more numbers than anybody should watch. Five of them, per service, cover almost every database and I/O problem that matters.

Queries per request, p95, per route. The repetition signal. A route whose p95 is in the hundreds is either doing something unusual or has an unbatched loop, and a sudden increase after a deploy is a regression with an obvious cause.

Pool acquisition wait, p99. The exhaustion signal. Anything above a few milliseconds sustained is worth attention, because a healthy pool hands out connections instantly.

Pool in use against pool size. The capacity headroom, drawn as two lines on one chart so saturation is a line touching a ceiling.

Slowest statement templates by total time. Total time rather than per-execution latency, because a moderately slow query executed ten thousand times an hour matters more than a very slow one executed twice. This ranking is what directs indexing work.

Outbound attempts per call. The retry signal. A value creeping above one means a dependency is failing and being retried, which costs latency and load and is often invisible from the dependency's own metrics.

Everything else — individual query spans, per-statement histograms, connection lifetime distributions — belongs in traces and ad-hoc queries rather than on a screen somebody is expected to read.

Reading a slow trace in order

With all three measurements in place, a slow request can be diagnosed in a fixed order that rarely takes more than a minute.

First, the acquisition time. If a large share of the request was spent waiting for a connection, nothing else about the queries matters yet — the pool is exhausted, and the investigation moves to observing connection pool exhaustion. This is checked first because it invalidates everything downstream: queries run after a long wait look fast, and they are.

Second, the query count. If the count is far above what the endpoint should need, the problem is repetition, and the most repeated statement names the loop. This is the most common finding by a wide margin.

Third, the slowest individual query. Only once acquisition and count are unremarkable does the duration of individual queries become the lead. A single slow statement usually needs an index, a rewrite or a smaller result set, and tracing slow SQL queries in Python covers finding it across the fleet rather than one trace at a time.

Fourth, the gaps. If acquisition, count and query durations together do not account for the request's duration, the remaining time is in Python between the calls, and at that point a profile — ideally linked to this span — is the right tool.

Common mistakes

Measuring only query duration. Error signature: slow requests whose traces show only fast queries. Root cause: repetition and acquisition are unmeasured. Remediation: add queries per request and pool acquisition time.

Recording parameter values. Error signature: personal data in span attributes, and a statement attribute with unbounded distinct values. Root cause: capturing executed SQL rather than the template. Remediation: sanitise to placeholders at instrumentation time.

One span per logical HTTP call. Error signature: a dependency that looks uniformly slow and is actually flapping. Root cause: retries hidden inside one span. Remediation: a span per attempt with the attempt number.

Losing context across a thread boundary. Error signature: database spans appearing as separate root traces. Root cause: synchronous drivers called on worker threads without context propagation. Remediation: carry the context into the thread explicitly.

Integer counters in async fan-out. Error signature: a query count far lower than the number of query spans in the trace. Root cause: child tasks increment their own copies of an immutable context value. Remediation: store a mutable counter object in the context.

Treating a cache hit ratio as one number. Error signature: a healthy-looking overall ratio and one endpoint that is slow for cache reasons. Root cause: a fleet-wide average hiding a poorly performing key pattern. Remediation: record hits and misses per bounded key pattern.

Enlarging the pool as the first response. Error signature: an exhausted pool that is exhausted again at the next peak, and a database closer to its connection limit. Root cause: treating acquisition wait as a capacity problem when connections are being held too long. Remediation: check how long connections are held per request before changing the pool size.

Frequently Asked Questions