Finding Slow ST_ Function Calls With pg_stat_statements

This page is the hands-on companion to pg_stat_statements for Spatial Workloads: you have the extension enabled and now need one query that reliably surfaces the slowest ST_ statements on a ride-hailing dispatch database, plus a way to tell which endpoint each one belongs to. The concrete goal is to answer, at 3 a.m. during a latency page, “which spatial statement is eating the database, and which route fires it?” — without guessing from application logs.

Why the Naive Approach Fails

The instinct is to open pg_stat_statements, sort by mean_exec_time descending, and blame whatever sits on top:

-- Misleading: highest mean is rarely the real problem
SELECT query, mean_exec_time
FROM pg_stat_statements
ORDER BY mean_exec_time DESC
LIMIT 10;

On a dispatch database this points at the wrong query almost every time. The top of that list is a nightly ST_Intersects coverage report over the whole trips table — genuinely slow per call, but run a handful of times a day, so its contribution to total load is a rounding error. Meanwhile the ST_DWithin nearest-driver lookup against driver_positions, at 2.4 ms mean but four million calls an hour, never appears near the top of a mean-sorted list even though it is where the database actually spends its time. Sorting by mean also tells you nothing about which endpoint issued the statement, so even after you find a slow query you are left grepping application code to locate it.

Production-Ready Implementation

The fix is one ranking query that orders by cumulative time with a share-of-total column, combined with an application-side convention that tags every spatial query with its endpoint. Below is the complete, copy-paste setup.

First, the ranking query. It filters to spatial calls, ranks by total_exec_time, and extracts the endpoint tag that the application prepends as a SQL comment:

-- Slowest ST_ statements by cumulative load, with endpoint and cache health
SELECT
    s.queryid,
    substring(s.query FROM '/\* endpoint:([a-z0-9_/-]+) \*/') AS endpoint,
    s.calls,
    round(s.mean_exec_time::numeric, 3)              AS mean_ms,
    round(s.total_exec_time::numeric / 1000, 1)      AS total_sec,
    round(100.0 * s.total_exec_time
          / sum(s.total_exec_time) OVER (), 1)       AS pct_of_total,
    round(100.0 * s.shared_blks_hit
          / nullif(s.shared_blks_hit + s.shared_blks_read, 0), 2) AS cache_hit_pct,
    left(regexp_replace(s.query, '\s+', ' ', 'g'), 100) AS query_sample
FROM pg_stat_statements s
WHERE s.query ILIKE '%st_dwithin%'
   OR s.query ILIKE '%st_distance%'
   OR s.query ILIKE '%st_intersects%'
   OR s.query LIKE '%<->%'
ORDER BY s.total_exec_time DESC
LIMIT 20;

For the endpoint column to resolve, the application must prepend a stable comment. In psycopg the query text carries a fixed /* endpoint:... */ marker, while the geometry and radius stay bound parameters so normalisation still collapses every call into one queryid:

import psycopg

# Stable comment → resolvable endpoint; literals stay parameterised
NEAREST_DRIVERS_SQL = """
    /* endpoint:dispatch/nearest-drivers */
    SELECT driver_id,
           ST_Distance(
               geom::geography,
               ST_SetSRID(ST_MakePoint(%(lon)s, %(lat)s), 4326)::geography) AS dist_m
    FROM driver_positions
    WHERE ST_DWithin(
              geom::geography,
              ST_SetSRID(ST_MakePoint(%(lon)s, %(lat)s), 4326)::geography,
              %(radius_m)s)
      AND status = 'available'
    ORDER BY geom <-> ST_SetSRID(ST_MakePoint(%(lon)s, %(lat)s), 4326)
    LIMIT %(limit)s;
"""


def nearest_drivers(conn: psycopg.Connection, lon: float, lat: float,
                    radius_m: float = 1500, limit: int = 10) -> list[tuple]:
    with conn.cursor() as cur:
        cur.execute(NEAREST_DRIVERS_SQL,
                    {"lon": lon, "lat": lat, "radius_m": radius_m, "limit": limit})
        return cur.fetchall()

Second, the scheduled snapshot. Reading pg_stat_statements once gives a lifetime total; to see trends you persist the spatial slice on an interval into a history table and difference consecutive rows. Create the sink once:

CREATE TABLE IF NOT EXISTS st_stmt_history (
    taken_at         timestamptz NOT NULL DEFAULT now(),
    queryid          bigint      NOT NULL,
    endpoint         text,
    calls            bigint      NOT NULL,
    total_exec_time  double precision NOT NULL,
    shared_blks_read bigint      NOT NULL,
    PRIMARY KEY (taken_at, queryid)
);

Then a scheduled worker inserts a snapshot and reports the per-window delta:

import psycopg

SNAPSHOT_INSERT = """
    INSERT INTO st_stmt_history (queryid, endpoint, calls, total_exec_time, shared_blks_read)
    SELECT
        queryid,
        substring(query FROM '/\\* endpoint:([a-z0-9_/-]+) \\*/'),
        calls, total_exec_time, shared_blks_read
    FROM pg_stat_statements
    WHERE query ILIKE '%st_dwithin%'
       OR query ILIKE '%st_distance%'
       OR query LIKE '%<->%';
"""

WINDOW_DELTA = """
    WITH ranked AS (
        SELECT queryid, endpoint, calls, total_exec_time, taken_at,
               lag(calls)           OVER w AS prev_calls,
               lag(total_exec_time) OVER w AS prev_total
        FROM st_stmt_history
        WINDOW w AS (PARTITION BY queryid ORDER BY taken_at)
    )
    SELECT endpoint, queryid,
           calls - prev_calls                          AS window_calls,
           round((total_exec_time - prev_total)::numeric, 1) AS window_ms,
           round(((total_exec_time - prev_total)
                  / nullif(calls - prev_calls, 0))::numeric, 3) AS window_mean_ms
    FROM ranked
    WHERE prev_calls IS NOT NULL
      AND calls - prev_calls > 0
      AND taken_at = (SELECT max(taken_at) FROM st_stmt_history)
    ORDER BY window_ms DESC
    LIMIT 20;
"""


def snapshot_and_report(dsn: str) -> list[dict]:
    with psycopg.connect(dsn, connect_timeout=5) as conn:
        with conn.cursor() as cur:
            cur.execute(SNAPSHOT_INSERT)
        conn.commit()
        with conn.cursor(row_factory=psycopg.rows.dict_row) as cur:
            cur.execute(WINDOW_DELTA)
            return cur.fetchall()

Schedule snapshot_and_report every one to five minutes. The WINDOW_DELTA query uses lag() over each queryid to compute exactly how much time and how many calls accrued in the latest window, ordered so the current heaviest spatial statement — resolved to its endpoint — sits at the top.

Configuration and Tuning Knobs

Keep the endpoint comment truly constant per route. Interpolating a trip ID or timestamp into it turns one statement into thousands of near-identical rows, overflowing the retention table and hiding the very hotspot you are hunting.

Verification Steps

Confirm the endpoint tag resolves. After traffic flows, the ranking query should show a non-null endpoint for your dispatch statements:

SELECT queryid,
       substring(query FROM '/\* endpoint:([a-z0-9_/-]+) \*/') AS endpoint,
       calls
FROM pg_stat_statements
WHERE query LIKE '/* endpoint:%'
ORDER BY total_exec_time DESC
LIMIT 5;

If endpoint is null, the comment is being stripped before the server sees it — some poolers remove comments, so confirm your pooler preserves them or move the marker inside the statement body.

Confirm the pattern stayed aggregated. A single high-calls row per endpoint means normalisation held; many low-count rows mean a literal leaked into the query text:

SELECT count(*) AS distinct_rows, sum(calls) AS total_calls
FROM pg_stat_statements
WHERE query LIKE '/* endpoint:dispatch/nearest-drivers %';

distinct_rows should be 1 (or a small number if you have a few plan variants). Confirm the snapshot deltas are sane by checking that window_calls from snapshot_and_report tracks the request rate your application emits for the same endpoint over the same window; when they agree, the database-side and application-side numbers are consistent.

Gotchas Checklist

• Sorting by mean hides the real hotspot. Always rank by total_exec_time (or a windowed delta of it). The dispatch proximity lookup dominates cumulative load despite a low per-call mean, and a mean-sorted list buries it under rare heavy reports.

• Cumulative counters need differencing. total_exec_time is a lifetime sum since the last pg_stat_statements_reset(). Graphing it raw produces an ever-rising line; difference consecutive snapshots to get a per-window rate that actually moves when latency regresses.

• Poolers can strip comments. A statement-level connection pooler may remove SQL comments, erasing the endpoint tag. Verify the marker survives to the server, or embed the route label inside the statement body where it cannot be stripped.

• Per-request comment values explode the table. The endpoint marker must be static per route. Any dynamic value — trip id, user id, timestamp — creates a fresh queryid per call, floods pg_stat_statements.max, and evicts the entries you care about.

• SRID must stay explicit and consistent. Every geometry here is SRID 4326; the ::geography casts and ST_SetSRID(..., 4326) keep the predicate index-eligible. A stray reprojection inside the WHERE clause both changes the plan and spawns a separate normalised statement, splitting your metric.

Frequently Asked Questions

How do I map a queryid back to the endpoint that issued it?

Prepend a stable SQL comment carrying the endpoint name to each query, as the Python helper above does with /* endpoint:dispatch/nearest-drivers */. The extension keeps the comment in the normalised text, so a simple substring match resolves each queryid to a route. Comments do not affect normalisation of the literal coordinates and radii that follow them, so every call from one endpoint still aggregates into a single row.

Why compute deltas instead of reading total_exec_time directly?

The total_exec_time column is cumulative since the last reset, so a single reading blends old and current behaviour into one number. Differencing two snapshots yields the time and calls added during that window, which is what reacts to a regression the moment it appears rather than being diluted by hours or days of history. The windowed lag() query does exactly this differencing inside the database.

Does the tracking comment change how the statement is normalised?

No. The comment is preserved verbatim while the literal coordinates and radii after it still collapse to placeholders, so all calls from one endpoint aggregate into a single queryid that also carries its route label. Keep the comment static — a per-request value such as a trip id would split the pattern into thousands of rows and defeat the aggregation entirely.

Related Topics

• pg_stat_statements for Spatial Workloads — parent topic covering enablement, normalisation, and reading the timing columns
• Spatial Performance Monitoring & Observability — the broader observability pipeline this feeds into
• Detecting GiST Index Bloat — investigate a statement whose shared_blks_read keeps climbing
• Query Plan Analysis with EXPLAIN — take a flagged queryid and confirm at the plan level why it is slow