Sampling EXPLAIN ANALYZE Under High QPS

Sampling EXPLAIN ANALYZE under high query volume means capturing enough instrumented plans to detect regressions while holding the added instrumentation cost to a fixed, provable fraction of production CPU and log bandwidth. This runbook documents the exact overhead budgets, the auto_explain settings that enforce them, an adaptive per-fingerprint sampler written for asyncio, and the tail-based selection logic that guarantees the slowest plans are never dropped even when the global sample rate is throttled to a fraction of a percent. It is the volume-control layer that sits in front of Routing EXPLAIN ANALYZE Output to Centralized Logs and depends on the low-impact capture primitives in Capturing EXPLAIN Plans Without Impacting Production Performance.

The failure mode is specific: an operator enables auto_explain globally to chase one slow query, the instrumentation timer fires on every execution at 12,000 queries per second, and the node’s p99 latency doubles while the log shipper falls hours behind. The fix is never “turn it off” — it is to sample deliberately, with a rate ceiling, a per-fingerprint budget, and a tail-preserving override.

Symptom Identification and Production Thresholds #

EXPLAIN ANALYZE forces per-node timing instrumentation, and on high-frequency short queries the gettimeofday calls dominate. Treat each of the following as a hard breach condition with an exact trigger, not a rule of thumb:

1. Capture overhead exceeds budget. Instrumented-execution CPU rises more than 3% above the uninstrumented baseline for the same workload window. Above 3% you are trading production latency for observability at a bad exchange rate.
2. Per-query timing tax. Median added latency per captured execution exceeds 0.8 ms, or p99 added latency exceeds 4 ms. On a 1.5 ms OLTP query, a 4 ms timing tax is a 260% inflation.
3. Sample rate above the ceiling. Effective auto_explain.sample_rate on any node serving more than 8,000 qps is above 0.01 (1%). At 12,000 qps, 1% is already 120 instrumented plans per second — past that the log path saturates before the CPU does.
4. Per-fingerprint flooding. A single normalized fingerprint emits more than 20 captured plans per minute. One hot query should never consume the whole capture budget; the interesting signal is one clean plan per fingerprint per interval, not a thousand copies.
5. Log-ship backlog. The centralized-log ingestion lag for plan events exceeds 30 seconds, or the local spool grows past 50 MB. A growing spool means capture is outrunning the shipper described in the routing guide, and plans are being buffered on the database host itself.
6. Tail starvation. Fewer than 95% of executions slower than the rolling p99 duration are captured. If throttling is dropping the slow tail, sampling has inverted its own purpose.

When conditions 3 and 5 fire together, drop the global rate immediately and let the adaptive sampler below re-derive a safe rate from measured overhead.

Root Cause Analysis #

Three failure domains produce runaway capture cost at high QPS. Each has a direct diagnostic.

Uniform sampling on a skewed workload. A flat sample_rate treats a 0.4 ms lookup and a 900 ms report identically, so the fast-and-frequent queries consume almost the entire capture budget and drown the rare slow plans you actually want. Confirm the skew before tuning by ranking fingerprints by call volume against mean time:

-- PostgreSQL: which fingerprints dominate call volume vs mean latency
SELECT queryid, calls, round(mean_exec_time::numeric, 3) AS mean_ms,
       round((100.0 * calls / SUM(calls) OVER ())::numeric, 2) AS pct_of_calls
FROM pg_stat_statements
ORDER BY calls DESC
LIMIT 15;

Any fingerprint above roughly 20% of pct_of_calls with a sub-millisecond mean_ms is a budget sink; it needs a per-fingerprint cap, not the global rate.

ANALYZE timing overhead on short queries. The instrumentation cost is dominated by the timing-source syscall, not by log volume. Measure the clock cost on the actual host — a slow clock source turns every node timer into a bottleneck:

# Is the kernel clocksource fast enough for per-node timing?
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
pg_test_timing   # ships with PostgreSQL; per-loop cost should be well under 100 ns

If pg_test_timing reports per-loop cost above ~100 ns (typically because the clocksource is hpet or acpi_pm rather than tsc), disable auto_explain.log_timing and rely on total duration only; per-node timing is unaffordable there.

Log-capture amplification. auto_explain.log_analyze with log_buffers and log_verbose can emit a plan document tens of kilobytes wide for a single query. At even 100 captures per second that is megabytes per second into the log path. Inspect what the current settings actually emit:

SELECT name, setting FROM pg_settings
WHERE name LIKE 'auto_explain.%'
ORDER BY name;

Verify auto_explain.log_analyze, log_buffers, and log_min_duration are set deliberately; a log_min_duration of 0 means every statement is a candidate, which is the classic amplification trigger.

Step-by-Step Remediation #

1. Set a conservative auto_explain floor. Instrument only genuinely slow statements and let the sampler handle the rest. These values cap the naive path before the adaptive layer even runs:

# postgresql.conf — load in session_preload_libraries, not shared_preload for ad-hoc control
auto_explain.log_min_duration = 500ms   # never instrument sub-500ms statements globally
auto_explain.sample_rate      = 0.005   # 0.5% ceiling; adaptive layer lowers further
auto_explain.log_analyze      = on
auto_explain.log_timing       = off     # off unless pg_test_timing < 100 ns/loop
auto_explain.log_buffers      = on
auto_explain.log_format       = json
auto_explain.log_min_duration = 500ms

2. Run the adaptive sampler in the capture agent. This decides, per execution, whether to keep the plan. It enforces a per-fingerprint token budget, backs the global rate off when measured overhead climbs, and always admits tail-slow executions. It is async, typed, and emits structlog events plus OpenTelemetry metrics so the sampler’s own decisions are observable.

from __future__ import annotations

import asyncio
import time
from dataclasses import dataclass, field

import asyncpg
import structlog
from opentelemetry import metrics, trace

log = structlog.get_logger("explain.sampler")
tracer = trace.get_tracer("explain.sampler")
meter = metrics.get_meter("explain.sampler")

_admitted = meter.create_counter("explain_capture_admitted_total")
_dropped = meter.create_counter("explain_capture_dropped_total")
_rate_gauge = meter.create_observable_gauge("explain_effective_sample_rate")

RATE_CEILING = 0.01          # 1% hard ceiling above 8k qps
RATE_FLOOR = 0.0005          # never drop below 0.05% or we see nothing
OVERHEAD_BUDGET_PCT = 3.0    # back off when instrumentation CPU exceeds 3%
FINGERPRINT_BUDGET = 20      # captures per fingerprint per 60s window
TAIL_QUANTILE_MS = 0.0       # set from rolling p99; anything slower is force-kept


@dataclass
class _Bucket:
    tokens: int
    window_start: float


@dataclass
class AdaptiveSampler:
    effective_rate: float = RATE_CEILING
    p99_ms: float = 250.0
    _buckets: dict[int, _Bucket] = field(default_factory=dict)

    def _refill(self, fingerprint: int, now: float) -> _Bucket:
        b = self._buckets.get(fingerprint)
        if b is None or now - b.window_start >= 60.0:
            b = _Bucket(tokens=FINGERPRINT_BUDGET, window_start=now)
            self._buckets[fingerprint] = b
        return b

    def observe_overhead(self, instrumented_pct: float) -> None:
        """Multiplicative back-off / additive recovery on the global rate."""
        if instrumented_pct > OVERHEAD_BUDGET_PCT:
            self.effective_rate = max(RATE_FLOOR, self.effective_rate * 0.5)
            log.warning("sample_rate_backoff", overhead_pct=round(instrumented_pct, 2),
                        new_rate=round(self.effective_rate, 5))
        elif self.effective_rate < RATE_CEILING:
            self.effective_rate = min(RATE_CEILING, self.effective_rate + 0.0005)

    def should_capture(self, fingerprint: int, duration_ms: float) -> bool:
        now = time.monotonic()
        # Tail override: the slow tail is always worth a plan, budget or not.
        if duration_ms >= self.p99_ms:
            self._admit(fingerprint, now, reason="tail")
            return True
        bucket = self._refill(fingerprint, now)
        if bucket.tokens <= 0:
            _dropped.add(1, {"reason": "fingerprint_budget"})
            return False
        # Deterministic stratified draw keyed on the monotonic clock fraction.
        if (now * 1000.0) % 1.0 > self.effective_rate:
            _dropped.add(1, {"reason": "rate"})
            return False
        bucket.tokens -= 1
        self._admit(fingerprint, now, reason="sampled")
        return True

    def _admit(self, fingerprint: int, now: float, reason: str) -> None:
        _admitted.add(1, {"reason": reason})
        log.debug("capture_admitted", fingerprint=fingerprint, reason=reason,
                  rate=round(self.effective_rate, 5))


async def refresh_p99(pool: asyncpg.Pool, sampler: AdaptiveSampler) -> None:
    """Keep the tail threshold current from live statement stats."""
    while True:
        with tracer.start_as_current_span("refresh_p99"):
            row = await pool.fetchrow(
                "SELECT percentile_cont(0.99) WITHIN GROUP (ORDER BY mean_exec_time) AS p99 "
                "FROM pg_stat_statements WHERE calls > 5"
            )
            if row and row["p99"] is not None:
                sampler.p99_ms = float(row["p99"])
                log.info("p99_refresh", p99_ms=round(sampler.p99_ms, 2))
        await asyncio.sleep(30.0)

3. Wire the sampler ahead of the log-ship handoff. The capture agent calls should_capture(fingerprint, duration_ms) on every completed execution and only forwards admitted plans to the spool, which the shipper in the routing guide drains. Feed the node’s measured instrumentation overhead back in via observe_overhead() on a 15-second cadence.

4. Confirm the effective rate settled. Under a 12,000 qps load with 3% overhead breaches, the sampler should converge to a rate near the floor while still admitting the tail. Expected structlog output during a back-off:

2026-07-18T09:14:02Z [warning] sample_rate_backoff overhead_pct=4.7 new_rate=0.005
2026-07-18T09:14:17Z [warning] sample_rate_backoff overhead_pct=3.4 new_rate=0.0025
2026-07-18T09:14:32Z [info]    p99_refresh p99_ms=812.44
2026-07-18T09:14:33Z [debug]   capture_admitted fingerprint=7714093 reason=tail rate=0.0025

The instrumentation-overhead handling here reuses the fail-closed spooling contract described in Building Async Ingestion Pipelines for High-Throughput Queries, so a saturated spool sheds load without stalling the query path.

Verification Checklist #

• [ ] Instrumented-execution CPU overhead is measured at or below 3% over a full peak-hour window.
• [ ] Effective auto_explain.sample_rate on every node above 8,000 qps is at or below 0.01.
• [ ] pg_test_timing per-loop cost is under 100 ns, or auto_explain.log_timing is disabled on that host.
• [ ] No single fingerprint emits more than 20 captured plans in any 60-second window.
• [ ] At least 95% of executions slower than the rolling p99 appear in centralized logs.
• [ ] Centralized-log ingestion lag for plan events stays under 30 seconds and the local spool never exceeds 50 MB.
• [ ] The adaptive sampler’s back-off and recovery are visible as explain_effective_sample_rate in your metrics backend.
• [ ] auto_explain.log_min_duration is a positive value (never 0) on every production node.

Compatibility and Engine-Specific Notes #

The sampling contract is portable, but the capture primitive is engine-specific.

MySQL has no in-server statement-sampling gate, so the adaptive sampler must run in the application or proxy layer and drive an out-of-band EXPLAIN ANALYZE against a replica for admitted fingerprints only — never inline on the serving path. Distributed engines that expose plan capture per-node (for example CockroachDB’s statement diagnostics) should apply the per-fingerprint budget per gateway node, since a single fingerprint can be admitted independently on each.

Related #

• ← Back to Routing EXPLAIN ANALYZE Output to Centralized Logs (parent topic)
• Low-impact capture primitives: Capturing EXPLAIN Plans Without Impacting Production Performance
• Downstream buffering and backpressure: Building Async Ingestion Pipelines for High-Throughput Queries
• Wider context: Automated EXPLAIN Capture & Storage Workflows