Attributing Read Latency to Replica Selection with Traces

Problem statement: p99 read latency doubled, the replicas look healthy, the pool looks fine, and three people are looking at three dashboards trying to work out which of them is wrong.

A read against a replica has at least three sequential phases, and an aggregate duration collapses them into one number that names none of them. Splitting the phases is a small instrumentation change that converts most latency investigations into a glance. It builds on the span attributes described in tracing and SLO reporting for replica reads.

Symptom Identification

You need phase attribution when:

  • Read latency rises and the database’s own mean_exec_time for the same statements has not moved.
  • Investigations routinely begin with “is it the database or the pool?” and take twenty minutes to answer.
  • Latency rises during lag events even for reads that were served successfully by a replica.
  • The p99 and p50 diverge sharply, which usually means a queue somewhere, but the queue is not identified.
  • A pool-size change and a replica addition are both proposed for the same symptom, with no evidence distinguishing them.

The third symptom is the most diagnostic and the most often misread. If a lag event raises latency for reads that succeeded on a replica, the extra time is being spent in the freshness gate rejecting candidates — not in the database at all.

Root Cause Analysis

A replica read has three sequential phases, each with a different failure mode.

Gate time — deciding which node may serve this read. Costs whatever the freshness check costs: near zero if lag is read from a cached value, several milliseconds if the gate queries each candidate synchronously. Grows when more candidates must be rejected before one qualifies, which happens precisely during lag events.

Checkout time — obtaining a connection to the chosen node. Near zero when the pool has idle connections; unbounded when it does not. This is queue time, and it is what makes p99 diverge from p50.

Execution time — the database running the query and returning rows. What pg_stat_statements measures, and the only phase visible from the database side.

Only the third is observable from the database. This is why database dashboards can look entirely healthy while application-observed latency doubles: the extra time was spent before the query was ever sent.

The three phases have different owners. Gate time belongs to whoever maintains the lag source and the routing policy. Checkout time belongs to pool configuration. Execution time belongs to query performance and replica capacity. Alerting on the total routes every alert to a triage step whose only job is to work out which of the three grew — a determination the instrumentation could have made automatically.

Three reads with the same total latency and three different causes Three waterfall bars of equal total length on a common millisecond axis. The first is dominated by the route selection phase, indicating the freshness gate is probing candidates synchronously. The second is dominated by pool checkout, indicating queueing for a connection. The third is dominated by execution, indicating a slow query or a saturated replica. Each is annotated with the team that owns the remedy, showing that an aggregate duration cannot route the alert. 0 ms 45 ms 90 ms read A route select — gate rejecting candidates → lag source read B pool checkout — waiting for a connection → pool sizing read C execute — slow query or saturated replica → query / capacity route select pool checkout execute Same p99 in all three. Only read C is visible from the database, which is why database dashboards can look clean.

Step-by-Step Resolution

Step 1 — Add three child spans

python
from opentelemetry import trace
tracer = trace.get_tracer("db.router")

def execute_read(sql, params, *, path: str, budget_s: float):
    with tracer.start_as_current_span("db.query") as parent:
        parent.set_attribute("db.read.path", path)

        with tracer.start_as_current_span("db.route.select") as gate:
            choice = router.select(budget_s)
            # Gate time is only interpretable with these two attributes.
            gate.set_attribute("db.replica.candidates_considered", choice.considered)
            gate.set_attribute("db.replica.candidates_rejected", choice.rejected_count)
            gate.set_attribute("db.replica.select_reason", choice.reason)

        with tracer.start_as_current_span("db.pool.checkout") as checkout:
            conn = choice.node.checkout()
            checkout.set_attribute("db.pool.idle_at_request", choice.node.pool.idle)
            checkout.set_attribute("db.pool.size", choice.node.pool.size)

        with tracer.start_as_current_span("db.execute"):
            rows = conn.execute(sql, params)

        return rows

Inline verification: a trace shows one db.query span with exactly three children whose durations sum to approximately the parent’s.

Step 2 — Record a histogram per phase

python
from opentelemetry import metrics
meter = metrics.get_meter("db.router")

PHASE = meter.create_histogram(
    "db.read.phase_duration", unit="ms",
    description="Duration of one phase of a replica read")

# Record on EVERY call, not only on sampled traces, so aggregate attribution
# is exact regardless of the sampling rate.
def _timed(phase: str, path: str, fn):
    t0 = time.perf_counter()
    try:
        return fn()
    finally:
        PHASE.record((time.perf_counter() - t0) * 1000,
                     {"db.read.phase": phase, "db.read.path": path})

Three phase values and a bounded set of paths keeps the series count small — the cardinality discipline described in OpenTelemetry span attributes for read replica routing decisions.

Inline verification: db_read_phase_duration_ms_count has exactly three distinct db_read_phase label values.

Step 3 — Build the stacked panel

promql
# One query per phase, stacked. A rising total now shows which band grew.
histogram_quantile(0.99, sum by (le) (
  rate(db_read_phase_duration_ms_bucket{db_read_phase="route_select"}[5m])))

histogram_quantile(0.99, sum by (le) (
  rate(db_read_phase_duration_ms_bucket{db_read_phase="pool_checkout"}[5m])))

histogram_quantile(0.99, sum by (le) (
  rate(db_read_phase_duration_ms_bucket{db_read_phase="execute"}[5m])))

Inline verification: during a deliberate pool exhaustion (drop pool_size temporarily on a canary instance), the checkout band grows and the other two do not.

Step 4 — Make gate time interpretable

Gate duration alone is ambiguous: 8 ms could be a slow lag source or a healthy gate rejecting six candidates. The rejection count disambiguates it.

promql
# Gate time per rejected candidate. Flat means the gate is scaling normally
# with the number of nodes it must consider; rising means the source is slow.
histogram_quantile(0.99, sum by (le) (
  rate(db_read_phase_duration_ms_bucket{db_read_phase="route_select"}[5m])))
/
clamp_min(avg(db_replica_candidates_rejected), 1)

Inline verification: during a lag event, gate time rises while gate-time-per-rejection stays flat — the gate is doing more work, not working more slowly.

Step 5 — Alert per phase

yaml
groups:
  - name: read-phase-latency
    rules:
      - alert: PoolCheckoutSlow
        expr: |
          histogram_quantile(0.99, sum by (le) (
            rate(db_read_phase_duration_ms_bucket{db_read_phase="pool_checkout"}[5m]))) > 50
        for: 5m
        labels: {severity: ticket, team: platform}
        annotations:
          summary: "Read pool checkout p99 above 50 ms — pool likely saturated"
          runbook: "/connection-routing-pooling-strategies/connection-pool-architecture-for-read-replicas/"

      - alert: RouteSelectSlow
        expr: |
          histogram_quantile(0.99, sum by (le) (
            rate(db_read_phase_duration_ms_bucket{db_read_phase="route_select"}[5m]))) > 20
        for: 5m
        labels: {severity: ticket, team: data-platform}
        annotations:
          summary: "Freshness gate p99 above 20 ms — check the lag source, not the databases"

      - alert: ReplicaExecuteSlow
        expr: |
          histogram_quantile(0.99, sum by (le) (
            rate(db_read_phase_duration_ms_bucket{db_read_phase="execute"}[5m]))) > 200
        for: 10m
        labels: {severity: ticket, team: data-platform}
        annotations:
          runbook: "/monitoring-observability-read-replicas/query-performance-analysis-on-read-replicas/"

Inline verification: each alert carries a distinct team label and a runbook link appropriate to its phase.

Configuration Snippet

python
# router.py — the shape that makes gate time small and predictable.
# The gate must NOT query replicas on the request path; a background poller
# keeps a cached view and the gate reads memory.
import threading, time

class LagCache:
    """Refreshed out of band. Reading it is a dictionary lookup, so gate
    time stays sub-millisecond regardless of how many nodes are considered."""
    def __init__(self, nodes, interval_s: float = 1.0):
        self._lag = {n.name: 0.0 for n in nodes}
        self._nodes, self._interval = nodes, interval_s
        threading.Thread(target=self._poll, daemon=True).start()

    def _poll(self):
        while True:
            for n in self._nodes:
                try:
                    self._lag[n.name] = n.measure_lag_ms()
                except Exception:
                    self._lag[n.name] = float("inf")   # fail closed
            time.sleep(self._interval)

    def lag_ms(self, name: str) -> float:
        return self._lag.get(name, float("inf"))

def select(budget_ms: float, cache: LagCache, nodes):
    considered = rejected = 0
    for n in nodes:                       # in balancer-preference order
        considered += 1
        if cache.lag_ms(n.name) <= budget_ms:
            return Choice(n, "eligible", considered, rejected)
        rejected += 1
    return Choice(PRIMARY, "fallback_lag", considered, rejected)

The background poller is the difference between a gate that costs microseconds and one that costs milliseconds per candidate. A gate that measures lag synchronously turns a lag event into a latency event even for reads it serves successfully — the request pays for every probe of every rejected node. Polling at one-second intervals costs one query per node per second regardless of traffic, and makes gate time independent of the fleet size.

Note the float("inf") on a failed measurement: a node whose lag cannot be determined is treated as maximally stale, so an unreachable lag source degrades toward the primary rather than toward serving unknown-freshness data.

Synchronous versus cached freshness gate as the fleet grows Gate duration plotted against the number of replicas considered. The synchronous gate, which queries each candidate on the request path, rises linearly and reaches tens of milliseconds at eight nodes. The cached gate, fed by a background poller, stays essentially flat below one millisecond regardless of node count, because selecting is a dictionary lookup. A shaded region marks where gate time becomes a visible share of total read latency. 40 ms 20 ms 0 gate time replicas considered → 2 4 6 8 gate time is now a visible share of read latency synchronous gate — one probe per candidate cached gate — a dictionary lookup, flat in node count A synchronous gate turns every lag event into a latency event, including for the reads it serves successfully.

Verification and Rollback

Confirm the phases sum to the whole:

promql
# The three phase means should account for the parent span's mean, within
# a small residual for instrumentation overhead.
sum(rate(db_read_phase_duration_ms_sum[5m]))
  / sum(rate(db_read_phase_duration_ms_count[5m]) / 3)

A large residual means time is being spent somewhere unmeasured — typically serialisation of a large result set, or a retry loop wrapping the whole call. Both are worth their own span once identified.

Confirm attribution works on a known cause:

bash
# Shrink the pool on one canary instance and confirm ONLY checkout grows.
curl -X POST localhost:9000/admin/pool -d 'size=2'
sleep 300
curl -X POST localhost:9000/admin/pool -d 'size=20'

If gate or execution time also moves, the phases are overlapping — usually because the checkout span is wrapping something that also executes.

Rollback. The child spans and the phase histograms revert independently:

yaml
instrumentation:
  phase_spans: true       # negligible cost; the diagnostic value is here
  phase_metrics: true     # three label values; cardinality risk is minimal

There is rarely a reason to disable either — the combined overhead is well under a percent of a millisecond-scale operation, and the cardinality added is three series per read path. If a rollback is needed for unrelated reasons, keep the phase metrics and drop the spans: the aggregate attribution is what resolves most incidents, and it survives without any trace export at all.

Edge Cases and Gotchas

Async runtimes attribute waiting time to the wrong phase

In an async framework, the time between await pool.acquire() returning and the next line executing includes event-loop scheduling delay, which is not pool queueing. Under high event-loop load this inflates the checkout phase and points investigations at the pool when the real constraint is CPU. Record event-loop lag as a separate signal, and treat a checkout-time rise that coincides with event-loop lag as a scheduling problem rather than a pool problem.

Retries hide inside a single parent span

If the router retries on a failed node, the parent span covers both attempts while the child spans cover only the last one — so the phases stop summing to the parent, and the residual is exactly the failed attempt. Either create a child span per attempt with an attempt-number attribute, or record the retry count on the parent so the residual is explicable.

Connection establishment is not pool checkout

A checkout that finds no idle connection and opens a new one pays TCP setup, TLS handshake and authentication — often tens of milliseconds — inside what your instrumentation calls “checkout”. That is a genuine cost but a different one from queueing, and it responds to a different fix (a larger minimum idle count rather than a larger maximum). Split it out with a db.pool.connect span when the checkout metric is high and the pool is not actually saturated.

FAQ

Why split a database call into three spans?

Because the three phases fail for entirely different reasons and are fixed by different people. Gate time grows when the freshness check probes more nodes or its lag source is slow. Checkout time grows when the pool is saturated. Execution time grows when the database is slow or the plan changed. A single duration cannot distinguish them, so every latency investigation begins by ruling two of them out manually.

Does adding child spans cost much?

Very little. Creating a span is on the order of microseconds and the phases being wrapped take milliseconds, so overhead is well under a percent. Export cost is bounded by sampling, and because the per-phase histograms are recorded on every call rather than every sampled call, aggregate attribution is exact regardless of the sampling rate.

What is a normal gate time?

Sub-millisecond when the freshness check reads a cached lag value, and several milliseconds if it queries each candidate replica synchronously. If gate time is a meaningful fraction of total read latency, the gate is probably making network calls it could avoid — cache the lag with a background poller instead of measuring it on the request path.

Should the phases be alerted on separately?

Yes, because the remedy differs. A checkout-time alert should reach whoever owns pool sizing; an execution-time alert should reach whoever owns query performance and replica capacity; a gate-time alert usually indicates a problem with the lag source rather than with the databases at all. Alerting only on the total forces every alert through a triage step the instrumentation could have done automatically.

← Back to Tracing & SLO Reporting for Replica Reads