# Correlating Tile Spans with PostGIS Query Plans

A trace tells you a tile request spent 118 milliseconds in PostGIS. It does not tell you whether that was an index scan over a dense extent or a sequential scan because a predicate stopped being index-eligible — and those have entirely different fixes. This guide closes the gap: stamp each query with its trace identifiers, capture the plan for slow executions, and join the two so a slow span resolves to the plan that produced it. It extends the tracing model in Distributed Tracing for Spatial Request Flows within Spatial Pipeline Orchestration & Observability, and it is the drill-down a breached p95 from Monitoring Vector Query p95 Latency leads into.

# Prerequisites

# Step-by-Step Implementation

# 1. Capture plans automatically for slow executions only

Capturing every plan is expensive and produces noise; capturing none leaves the trace unexplained.

# postgresql.conf — plan capture for the executions that matter.
shared_preload_libraries = 'auto_explain,pg_stat_statements'

# Only executions above the tile service's own budget. Below this, the trace's
# span duration is sufficient and a plan adds nothing.
auto_explain.log_min_duration = '150ms'
auto_explain.log_analyze = on              # actual rows and timing, not estimates
auto_explain.log_buffers = on              # distinguishes a cold cache from a bad plan
auto_explain.log_timing = off              # per-node timing is costly; omit at first
auto_explain.log_format = 'json'           # parseable in the log pipeline
auto_explain.log_nested_statements = on

# The application_name carries the trace context into every log line.
log_line_prefix = '%m [%p] app=%a '

Verify capture fires at the threshold and not below it:

psql "$PG_DSN" -c "SELECT pg_sleep(0.05);"     # no plan expected
psql "$PG_DSN" -c "SELECT pg_sleep(0.20);"     # plan expected
grep -c 'auto_explain' /var/log/postgresql/postgresql.log

# 2. Stamp the trace context onto every query

application_name is the cheapest reliable channel: it appears in the log prefix and in pg_stat_activity without any query rewriting.

# traced_pool.py — trace identifiers travel with the connection checkout.
from opentelemetry import trace


def checkout(pool, ctx):
    """Set application_name to the current trace and span before running the tile
    query. This is what lets a plan in the Postgres log be joined to the span that
    caused it — without it, a slow plan and a slow span are two unrelated facts."""
    span = trace.get_current_span().get_span_context()
    app_name = f"tile|{span.trace_id:032x}|{span.span_id:016x}|{ctx.product}"
    conn = pool.getconn()
    with conn.cursor() as cur:
        # Truncated by Postgres at NAMEDATALEN; keep the trace id first so it survives.
        cur.execute("SET application_name = %s", (app_name[:63],))
    return conn


def add_span_attributes(span, ctx, rows: int, plan_captured: bool) -> None:
    """Mirror the join key onto the span, so the correlation works from either end."""
    span.set_attribute("db.system", "postgresql")
    span.set_attribute("mesh.product", ctx.product)
    span.set_attribute("mesh.crs", ctx.crs)
    span.set_attribute("mesh.bbox", ctx.bbox_wkt)
    span.set_attribute("mesh.rows_returned", rows)
    span.set_attribute("db.plan_captured", plan_captured)

Verify the identifiers reach the server intact — truncation at 63 characters is the usual surprise:

psql "$PG_DSN" -c "SELECT application_name FROM pg_stat_activity WHERE application_name LIKE 'tile|%' LIMIT 3;"

# 3. Join spans to plans in the log store

-- correlate.sql — one row per slow tile query, with its plan and its span.
-- Run against the log store, where Postgres logs and span records both land.
WITH plans AS (
    SELECT
        split_part(split_part(app_name, '|', 2), '|', 1) AS trace_id,
        split_part(app_name, '|', 3)                     AS span_id,
        duration_ms,
        plan_json,
        -- The single most useful derived field: did the planner reach the index?
        (plan_json::text LIKE '%"Node Type": "Seq Scan"%')          AS had_seq_scan,
        (plan_json::text LIKE '%"Index Cond"%')                     AS used_index
    FROM postgres_logs
    WHERE source = 'auto_explain' AND app_name LIKE 'tile|%'
)
SELECT
    s.trace_id, s.name AS span_name, s.duration_ms AS span_ms,
    p.duration_ms AS query_ms,
    s.attributes ->> 'mesh.product' AS product,
    s.attributes ->> 'mesh.bbox'    AS bbox,
    p.had_seq_scan, p.used_index,
    p.plan_json
FROM spans s
JOIN plans p ON p.trace_id = s.trace_id AND p.span_id = s.span_id
WHERE s.duration_ms > 300
ORDER BY s.duration_ms DESC;

Verify the join actually matches — an empty result usually means the identifier formatting differs between the two sides:

psql "$LOGSTORE_DSN" -f correlate.sql | head -20

# 4. Turn the correlation into a signal, not a manual query

# plan-quality-rules.yaml — sequential scans on the tile path are always a defect.
groups:
  - name: tile_plan_quality
    rules:
      - record: tile:seq_scan_ratio:30m
        expr: |
          sum(rate(tile_query_plans_total{had_seq_scan="true"}[30m])) by (domain, product)
          / sum(rate(tile_query_plans_total[30m])) by (domain, product)

  - name: tile_plan_alerts
    rules:
      - alert: TileQueryLostItsIndex
        expr: tile:seq_scan_ratio:30m > 0.01
        for: 15m
        labels: { severity: ticket }
        annotations:
          summary: "{{ $labels.product }} tile queries are sequential-scanning"
          description: >-
            A predicate has stopped being index-eligible — usually a function wrapping
            the geometry column, or an SRID mismatch forcing an implicit transform.

# Configuration Reference

# Common Failure Modes & Fixes

The join returns nothing. Root cause: application_name truncated at 63 characters, losing the span id. Fix: put the trace id first and keep the product last; verify from pg_stat_activity rather than from the client’s intent.

Plans are captured for everything and the log volume explodes. Root cause: log_min_duration set at or near zero. Fix: set it above the tile budget; the trace already covers the fast path.

A slow span has no plan. Root cause: the time was not spent in the query — it was connection acquisition, serialization, or the encoder. Fix: this is a useful result. Add spans around pool checkout and MVT encoding so the gap is attributable.

seq_scan_ratio alerts and the query looks unchanged. Root cause: an SRID mismatch introduced upstream, forcing an implicit transform that makes the index unusable. Fix: assert the SRID at ingest; the query text is identical, which is why the plan rather than the query is the evidence.

Plans reveal data volumes to consumers. Root cause: plan output surfaced in a consumer-visible error. Fix: plans belong in the log store behind domain access controls, never in a response.

# FAQ

# Related

• Distributed Tracing for Spatial Request Flows — the parent topic and the sampling strategy
• Monitoring Vector Query p95 Latency — the SLI whose breach leads here
• Propagating Trace Context Through Tile Pipelines — how the trace reaches the tile service