Find the cause of the 13-15 s realtime list_changes spikes #325

Key: SPR-18 · Type: HITL · Part of: #327 · Blocked by: none · Checked against: 3bb26de

Problem

Supabase Realtime's realtime.list_changes poll has taken 13-15 s at least three times, and we do not know why or whether it still happens.

On 2026-09-28 the HoE (the review's lead agent) read pg_stat_statements on prod. Three list_changes rows show a lifetime max_exec_time of 13,406 ms, 14,959 ms and 14,540 ms. The mean per call is about 5 ms. So one poll ran about 3,000 times slower than normal.

Realtime delivers chat postgres_changes events after each poll. So a 15 s poll probably delays new chat messages for every open chat by up to 15 s [pred].

max_exec_time is a lifetime value with no timestamp. It cannot show when a spike happened, or whether a spike happened this week. This issue finds out, with read-only checks first. It closes if no spike appears in 7 days.

There is no repo change in this issue. Every step that reads prod is for the maintainer.

Context

Labels: [prod] = read on prod by the HoE, 2026-09-28. [local] = local Docker Supabase stack, PostgreSQL 15.8. [repo] = this tree. [pred] = predicted, not measured.

What list_changes is. Supabase Realtime calls realtime.list_changes(...) about 2 times per second. Each call reads the logical replication slot supabase_realtime_replication_slot_... (plugin wal2json) and returns row changes for the published tables. Our chat postgres_changes subscriptions switch the poller on. It keeps polling for about 11 minutes after the last subscriber leaves, then stops [local, Realtime v2.130.0].

Who subscribes [repo].

The publication is defined in packages/supabase/scripts/17-realtime-replica.sql ~18 (create publication supabase_realtime) with 5 tables. packages/supabase/scripts/07-4-push-notifications-pgmq.sql ~703 adds push_subscriptions. Prod publishes 7 tables: users, channels, messages, channel_members, channel_message_counts, push_subscriptions, email_queue [prod]. email_queue has no source in the repo.

The five list_changes rows [prod, lifetime to 2026-09-28 10:27Z]. Each Realtime server version produces its own query text, so each has its own queryid.

• The three max values (13,406 / 14,959 / 14,540 ms) were read on 2026-09-28. Nobody recorded which queryid each belongs to. Step 1 does that.
• Only -937396806128081 still runs. In a 69.8-minute window it made 5,659 calls per hour at about 5 ms each. That is 27.3 s of DB time per hour, 0.76% of one core [prod].
• The current row is about 46 days old at 1.97 calls/s, or about 58 days at the 1.57 calls/s window average. So it started between about 2026-08-01 and 2026-08-13 [pred]. The other four rows stopped before that [pred].

Hypothesis H1: one large transaction from cron job cleanup-cron-job-run-details.

• The job is defined in packages/supabase/scripts/16-cron-jobs.sql ~41-56. It runs daily at 04:15 UTC ('15 4 * * *'). It deletes cron.job_run_details rows older than 7 days, but keeps each job's newest success [repo].
• On prod it is job 37. It was added on 2026-09-21, and the performance review dates its first run to that day [prod].
• The table's lifetime delete count is n_tup_del = 861,693 [prod]. Later daily runs are included in that count, so the first run deleted most of it, in one transaction [pred]. Step 1 reads the exact count.
• The table now holds 25,898 rows, 18 MB [prod].
• Logical decoding must read and reorder every transaction in the WAL. That includes tables outside the publication, such as cron.job_run_details.
• Local bench, run 1: one transaction that inserted 800,000 rows into an unpublished table made the next poll take 1,654 ms. The slot spill counters then read 29 transactions, 3,765 MB [local].
• In run 1, the 50 idle polls after that transaction had p50 459 ms and max 504 ms [local].
• Run 2 gave 1,656 ms for the same poll, 565 MB of spill, and idle polls after it up to 465 ms [local].
• Normal idle polls: p50 0.47 ms, max 206 ms [local].
• Gaps, so H1 is plausible, not proven:
  • The bench inserted 100-byte rows. Job 37 ran deletes, which write different WAL records.
  • The local host has 18 cores. Prod is probably Small, with 2 shared cores [pred]. A 10x slower poll on prod is a guess, not a measurement.
• Now the job deletes about one day of rows per run, roughly 3,700 [pred]. So H1 should not recur.

H1 explains at most one of the three spikes. Job 37 first ran on 2026-09-21. Only the current row (-937396806128081) ran after that date. A max on any other row happened before the current row started, in early August 2026 or earlier [pred]. So something else caused it.

Other candidates (not tested).

• H2: another large transaction. Examples: the weekly cleanup_old_document_views (job 10), the monthly partition job (job 9), a db push, or a bulk import.
• H3: a host stall. The instance has 2 shared cores [pred]. A CPU or disk stall slows one poll.
• The Realtime slot check (queryid 5991460940410430539, 3,043 calls, mean 21.69 ms) is a separate query. Slot creation waits for open transactions when Realtime starts. Read its max too, for context.

Limits of the evidence.

• pg_stat_statements stores no timestamps. max_exec_time never goes down. A new spike shows only if it beats the old max.
• A full pg_stat_statements_reset() would erase every lifetime counter, including the baseline for Ship and measure the cron-health sampling change #323. Never run the no-argument form.
• On 2026-09-28, edge log retention reached back to about 2026-08-22 [prod]. So any spike before then cannot be traced in logs. The log backend also failed on some queries that day [prod].
• cron.job_run_details keeps 7 days. The row for job 37's first run expires on the next 04:15 UTC run after it turns 7 days old. If the first run was 2026-09-21, its row goes at 04:15 UTC on 2026-09-29. So step 1 reads it first.

What to do

1. [maintainer] Read job 37's first runs now, before they expire. Run this read-only query in the SQL editor. Paste the result into this issue.

   select d.runid, d.status, d.return_message, d.start_time, d.end_time,
          d.end_time - d.start_time as took
   from cron.job_run_details d
   join cron.job j using (jobid)
   where j.jobname = 'cleanup-cron-job-run-details'
   order by d.start_time
   limit 10;

   return_message shows the command tag, for example DELETE 861693. If the first run is already gone, write "expired" and go on.

2. [maintainer] Map the three max values and read the slot counters. Run this read-only SQL. Paste the result.

   select queryid, calls,
          round(mean_exec_time::numeric, 3)  as mean_ms,
          round(stddev_exec_time::numeric, 1) as stddev_ms,
          round(max_exec_time::numeric, 1)    as max_ms
   from pg_stat_statements
   where query ilike '%realtime.list_changes%'
   order by calls desc;
   
   select queryid, calls, round(mean_exec_time::numeric, 1) as mean_ms,
          round(max_exec_time::numeric, 1) as max_ms
   from pg_stat_statements
   where queryid = 5991460940410430539;
   
   select slot_name, spill_txns, spill_count, pg_size_pretty(spill_bytes) as spill,
          stream_txns, total_txns, pg_size_pretty(total_bytes) as total, stats_reset
   from pg_stat_replication_slots;
   
   show logical_decoding_work_mem;

   Read the result like this:

   • Max on -937396806128081 above 13,000 ms: H1 fits that spike. Go to step 3.
   • Max on -937396806128081 below 1,000 ms: all three spikes predate the current row, so early August 2026 or earlier [pred]. They are outside log retention. Record "historic, cause unknown" and go to step 4.
   • Max on -937396806128081 between 1,000 and 13,000 ms: record it as a smaller spike on the current row, and do step 3.
   • Large spill_bytes on the wal2json slot supports the "large transaction" class (H1 or H2). The counters may cover only the current slot, because Realtime can recreate its slot on restart. A null stats_reset means the counters were never reset.

3. [maintainer] Search the Realtime logs around job 37's first run. Open Dashboard → Logs → Logs Explorer. Set the time picker to one hour: the first-run hour from step 1, for example 2026-09-21 04:00-05:00 UTC. Run:

   select timestamp, event_message
   from realtime_logs
   order by timestamp
   limit 200

   If that source name fails, pick the Realtime source from the Logs Explorer source list. Look for errors, timeouts, slot or replication messages, and reconnects in the minutes after 04:15. Run one hour per query. Realtime may not log a slow poll at all, so an empty result does not refute H1. Paste what you find, without any user data.

4. [maintainer] Choose how to watch for new spikes, then start a 7-day window. Two options.

   Option	What it does	Cost
   A. Per-query reset (recommended)	Resets only the current list_changes row, so its max_exec_time starts from 0	One write to prod. It erases that row's lifetime totals. No other row changes.
   B. No reset	Keep reading the lifetime max	A new spike shows only if it beats 14,959 ms. Weak.

   For option A, do these in order:

   • Save a snapshot of the row first: run the first query of step 2 and paste it here.

   • Check that Ship and measure the cron-health sampling change #323's one-hour before/after measurement is not running. That measurement reads the same row.

   • Run exactly this, and nothing wider:

     select pg_stat_statements_reset(0, 0, -937396806128081);

   • If it fails with a permission error, stop. Do not use any "reset all statistics" button. Use option B.

   • Record the start time in UTC. The window must not span a Postgres upgrade (Upgrade prod Postgres from 15.8.1.073 #322), a compute change or a project restart. If one happens, restart the window.

5. [maintainer] Read the row once a day for 7 days. Read it at about 05:00 UTC, after job 37's daily run at 04:15. Add one row per day to a table in this issue.

   select now(), calls, round(mean_exec_time::numeric, 3) as mean_ms,
          round(max_exec_time::numeric, 1) as max_ms
   from pg_stat_statements
   where queryid = -937396806128081;
   
   select slot_name, spill_txns, pg_size_pretty(spill_bytes) as spill
   from pg_stat_replication_slots;

   A spike here means max_ms at or above 1,000 ms. The daily read puts any spike inside one 24-hour span.

6. [maintainer] If a spike appears, trace it in that 24-hour span.

   • Cron runs that took long or touched many rows:

     select j.jobname, d.status, d.return_message, d.start_time,
            d.end_time - d.start_time as took
     from cron.job_run_details d join cron.job j using (jobid)
     where d.start_time >= now() - interval '1 day'
       and (d.end_time - d.start_time > interval '1 second'
            or d.return_message ~ '^(DELETE|UPDATE|INSERT) .*[0-9]{5,}$')
     order by d.start_time;

   • A job that calls a function (select public.some_fn()) logs only 1 row, whatever it changed. For those jobs, look at took.

   • Any db push, migration or bulk import that day. supabase_migrations.schema_migrations stores no apply time, so use the maintainer's own push record.

   • Realtime logs for that day, one hour per query, as in step 3.

   • Host CPU and memory for that day in the dashboard. Measure prod memory, swap and CPU for 7 days before any compute change #324 collects the same charts.

7. [agent] Write the outcome comment from the maintainer's numbers. Use the table under Verification. If the result needs a code or SQL change, draft a follow-up issue. Put the numbers in it, and write "Part of [Tracking] Supabase prod security and performance review, 2026-09-28 #327".

   Result after 7 days	Outcome
   No max_ms at or above 1,000 ms	Close. Record "one-off; H1 most likely" if step 2 put a spike on the current row, else "historic, cause unknown".
   Spike, and step 6 shows job 37 deleted 10,000 rows or more that day	Job 37 still makes a large transaction. Open a follow-up with the return_message counts.
   Spike, and step 6 shows another large cron, push or import transaction that day	H2. Open a follow-up naming that job and its row count.
   Spike with no large transaction found	H3 or a Realtime fault. Open a Supabase support ticket with the times, and link it here.

Out of scope

• The cron-health sampling change and its one-hour measurement: Ship and measure the cron-health sampling change #323.
• Host memory, swap and CPU, and any compute change: Measure prod memory, swap and CPU for 7 days before any compute change #324.
• The Postgres upgrade: Upgrade prod Postgres from 15.8.1.073 #322.
• Parked query work and the do-not-do list: Parked Supabase query changes and when to reopen them #326. That includes trimming the publication (RT-2) and moving chat from postgres_changes to broadcast.
• The general list_changes poll cost (about 5 ms, 2 times per second). It is accepted. This issue is only about the rare 13-15 s polls.

Acceptance criteria

• Job 37's first-run rows (or "expired") are pasted in this issue.
• Each of the three max values (13,406 / 14,959 / 14,540 ms) is mapped to a queryid.
• Slot spill counters and logical_decoding_work_mem are pasted, with stats_reset.
• Realtime logs for job 37's first-run hour were searched, and the finding (or "nothing logged") is recorded.
• The watch option (A or B) is recorded. For A, the pre-reset snapshot and the reset time in UTC are pasted.
• Seven daily readings are in a table in this issue, and the window crossed no upgrade, compute change or restart.
• The outcome row from step 7 is recorded. Any follow-up issue is linked.
• No full pg_stat_statements_reset() was run.

Verification

• After option A, the current row restarts from a small count:

  select calls, max_exec_time from pg_stat_statements where queryid = -937396806128081;

  Expected: calls well under 10,000 in the first hour, and max_exec_time under 1,000 ms.

• The reset touched no other row. The other four list_changes rows still show their lifetime calls from the Context table.

• Pass after 7 days: max_exec_time on -937396806128081 stays under 1,000 ms, and mean stays about 5 ms.

• git status shows no change from this issue. It is measurement only.

House rules

• No commits unless the maintainer asks. Commits go through /commit-review only.
• Agents have no prod access. Every prod read or write is a [maintainer] step, and the only prod write here is the one per-query reset in step 4.
• If a follow-up needs SQL, edit packages/supabase/scripts/*.sql first, then add a paired migration. Then run bun run --filter @docs.plus/supabase_back types. Never edit an applied migration. Never hand-edit seed.sql or apps/webapp/src/types/supabase.ts.
• The chat Realtime design is settled: postgres_changes stays on the public chatroom:{id} topic (apps/webapp/src/components/chatroom/CLAUDE.md ~50 and ~58). Do not fix a spike by moving chat to broadcast.
• Bun only. Never run npm, npx, yarn or pnpm in this repo.