Logging Spatial Query Performance with Structured Logs

Emit one JSON record per spatial query carrying query_id, bbox, crs, row_count, geom_bytes, duration_ms, and cache_hit, timed by a decorator and tied together with a per-session correlation_id, so you can reconstruct exactly which query slowed a user’s map — and why.

Jump to heading# Why this matters

Metric dashboards tell you the p95 spatial query is slow this afternoon; they cannot tell you it was the parcels layer, filtered to a bounding box over the city centre, returning 180,000 rows on a cache miss. That level of forensic detail belongs in structured logs — records where every field is a named, typed value rather than a fragment of an unparseable sentence. A free-text line like "query took 3.2s" is invisible to a log query engine, whereas {"duration_ms": 3200, "layer": "parcels", "cache_hit": false} can be filtered, aggregated, and alerted on. Structured logging is the high-cardinality complement to the Prometheus instruments described in Monitoring & Observability in Production: metrics hold the bounded aggregates, logs hold the per-query context that would blow up a metric’s cardinality. The cache_hit field in particular ties each record back to the query result cache, so a falling hit ratio can be traced to the exact queries that missed.

The diagram below shows how a per-session correlation ID threads through every query record emitted during one user interaction.

Jump to heading# Prerequisites

• Python 3.10+ with streamlit>=1.32 or panel>=1.3.
• structlog>=24.1 (the examples use it; the standard logging module with a JSON formatter works identically).
• geopandas>=0.14 and shapely>=2.0 for the query and geometry sizing.
• A log store or aggregator that can parse JSON lines and filter on fields.

Jump to heading# Step-by-step solution

Jump to heading# Step 1 — Configure a JSON formatter

Structured logging starts with rendering every record as a single JSON object. With structlog, chain a timestamp, a level, and the JSONRenderer so the output is one machine-parseable line per event:

import structlog

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,   # pulls in the correlation_id
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.JSONRenderer(),
    ],
)
log = structlog.get_logger("spatial.query")

If you prefer the standard library, attach a JSON formatter to the root handler instead — the field discipline in the following steps is identical, only the emitter changes.

Jump to heading# Step 2 — Define the spatial log schema

Agree on a fixed field set so every record is comparable. These seven fields describe a spatial query completely without embedding the geometry itself:

Jump to heading# Step 3 — Time the query with a decorator

Wrap the query in a decorator that measures wall-clock time and emits the record on completion, whether the call succeeds or raises. Computing geom_bytes from the WKB size gives a payload proxy without logging the geometry:

import time
import uuid
import functools
import geopandas as gpd

def log_spatial_query(layer: str):
    """Decorator: time a spatial query and emit one structured record."""
    def decorator(fn):
        @functools.wraps(fn)
        def wrapper(bbox, crs="EPSG:4326", *args, **kwargs):
            query_id = uuid.uuid4().hex[:12]
            t0 = time.perf_counter()
            status = "ok"
            gdf = None
            try:
                gdf = fn(bbox, crs, *args, **kwargs)
                return gdf
            except Exception:
                status = "error"
                raise
            finally:
                dur_ms = round((time.perf_counter() - t0) * 1000, 1)
                geom_bytes = (
                    int(gdf.geometry.to_wkb().str.len().sum())
                    if gdf is not None and len(gdf) else 0
                )
                log.info(
                    "spatial_query",
                    query_id=query_id,
                    layer=layer,
                    bbox=[round(c, 3) for c in bbox],   # coarse precision
                    crs=crs,
                    row_count=0 if gdf is None else len(gdf),
                    geom_bytes=geom_bytes,
                    duration_ms=dur_ms,
                    cache_hit=kwargs.get("cache_hit", False),
                    status=status,
                )
        return wrapper
    return decorator

@log_spatial_query(layer="parcels")
def fetch_parcels(bbox, crs="EPSG:4326", cache_hit=False):
    minx, miny, maxx, maxy = bbox
    return gpd.read_postgis(
        "SELECT geom, parcel_ref FROM parcels "
        "WHERE geom && ST_MakeEnvelope(%(a)s,%(b)s,%(c)s,%(d)s,4326)",
        _engine, geom_col="geom",
        params={"a": minx, "b": miny, "c": maxx, "d": maxy},
    )

Prefer a context manager (with timed_query(...) as rec:) when a single logical operation spans several queries and you want to attach fields incrementally — the timing and emit logic are the same, only the call shape differs.

Jump to heading# Step 4 — Bind a correlation ID per session

A single user interaction — pan the map, change a filter — can fire several queries. A correlation_id bound once per session lets you reconstruct the whole sequence later. Bind it into structlog’s context variables so every subsequent record inherits it automatically:

import uuid
import structlog
import streamlit as st

def bind_session_correlation():
    """Call once at the top of the Streamlit script."""
    if "correlation_id" not in st.session_state:
        st.session_state["correlation_id"] = uuid.uuid4().hex
    structlog.contextvars.bind_contextvars(
        correlation_id=st.session_state["correlation_id"]
    )

bind_session_correlation()
fetch_parcels((-0.13, 51.50, -0.11, 51.52))   # inherits correlation_id

Because the merge_contextvars processor is first in the chain (Step 1), the bound correlation_id is injected into every record without being passed explicitly. In Panel, bind it in pn.state.onload keyed on pn.state.curdoc instead of st.session_state.

Jump to heading# Step 5 — Query the logs

The payoff of structured fields is queryability. To find the slowest layers over a window, aggregate duration_ms by layer; to reconstruct one user’s session, filter by correlation_id. Expressed as SQL over a table of parsed JSON records:

-- p95 duration and cache-hit ratio per layer
SELECT layer,
       approx_percentile(duration_ms, 0.95)          AS p95_ms,
       avg(CASE WHEN cache_hit THEN 1 ELSE 0 END)    AS hit_ratio,
       max(row_count)                                AS max_rows
FROM spatial_query_logs
WHERE ts > now() - interval '1 hour'
GROUP BY layer
ORDER BY p95_ms DESC;

-- Replay every query in one slow session
SELECT ts, layer, bbox, row_count, duration_ms, cache_hit
FROM spatial_query_logs
WHERE correlation_id = '7f3a9c2e5b18'
ORDER BY ts;

Jump to heading# Verification

Capture the emitted JSON in-process and assert every required field is present and well-typed before shipping to production:

import json
import io
import structlog

buf = io.StringIO()
structlog.configure(
    processors=[structlog.processors.JSONRenderer()],
    logger_factory=structlog.PrintLoggerFactory(file=buf),
)

fetch_parcels((-0.13, 51.50, -0.11, 51.52), cache_hit=False)

record = json.loads(buf.getvalue().splitlines()[-1])
for field in ("query_id", "bbox", "crs", "row_count",
              "geom_bytes", "duration_ms", "cache_hit"):
    assert field in record, f"missing log field: {field}"
assert isinstance(record["duration_ms"], (int, float))
assert isinstance(record["cache_hit"], bool)
print("structured log schema OK:", record)

A passing run prints a single JSON object with all seven fields populated. If geom_bytes is unexpectedly zero on a non-empty result, the geometry column name differs from geometry — pass the correct geom_col when computing the WKB size.

Jump to heading# Edge cases and gotchas

• Logging full geometries bloats the store. A single complex MultiPolygon can serialise to megabytes of WKT. Emitting that per query multiplies your log volume by orders of magnitude and slows ingestion to a crawl. Log the rounded bbox and the geom_bytes size instead; if you need the exact geometry to reproduce an issue, store it in the database keyed by query_id and keep it out of the log line entirely.
• PII hiding in coordinates. A bounding box tight around a single dwelling, or a precise click coordinate, is effectively personal location data. Round coordinates before logging (the decorator rounds to three decimals, roughly 100 m), and for restricted datasets log only a coarse region identifier. Treat any field that can pinpoint an individual with the same access controls and retention limits you apply to other personal data.
• High-cardinality fields as index keys. query_id and correlation_id are unbounded by design. Indexing them as primary keys inflates index size and cost the same way an unbounded metric label does. Keep them searchable but aggregate on bounded fields — layer, crs, cache_hit, status — and let the high-cardinality fields serve only point lookups and session replay.

Jump to heading# FAQ

Back to Monitoring & Observability in Production

Related

• Monitoring & Observability in Production — where structured logs sit alongside metrics and traces in the full telemetry stack
• Adding Health-Check Endpoints to Streamlit Dashboards — the liveness and readiness probes that complement query logging
• Query Result Caching — the cache layer whose outcome the cache_hit field records