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: 0b302b2

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 an agent read pg_stat_statements on prod, read-only. 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.

Status: Steps 1-3 read 2026-10-25. #323 hour done 2026-11-07. Next: post the reads, push #755, wait for its clean 24 h GlitchTip read, then the step 4 reset.

Benchmark

Other measures for this window:

Context

Labels: [prod] = read on prod by an agent, read-only, 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 (create publication supabase_realtime). The repo publishes four tables: channels, messages, channel_members and channel_message_counts. Migration 20260930120100 dropped push_subscriptions, and 20261009120500 dropped users. Prod may also hold email_queue, which has no source in the repo. #322 step 1 records the full prod list.

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].
• 2026-11-07 (Ship and measure the cron-health sampling change #323 window): list_changes took 40,671 ms of 49,464 ms DB time in one hour (82 %).
• 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].
• A Realtime upgrade makes a new queryid. Step 4 and step 5 check which row is live, so a read never watches a dead row.

The live row spiked after 2026-09-28. The live row reached 14,561.2 ms between 2026-09-28 and 2026-10-25. That is after job 37's first run, so H1 (first run) does not explain it. Treat the spike as recurring (H2, H3 or other) until the 7-day window shows otherwise.

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].

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].
• pg_stat_replication_slots returned 0 rows on 2026-10-25, because no subscriber held a slot. So every slot read opens a chat first.

What to do

1. [maintainer] Record job 37's earliest kept runs (read 2026-10-25). 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.

   The step 1-3 output from 2026-10-25 goes in one comment titled "Reads from 2026-10-25", with user data removed. Post counts and timings only. Post it before the Revoke anon and public EXECUTE on three invoker notification RPCs #755 push. Write "not kept, now expired" for any lost value.

2. [maintainer] Map the three max values and read the slot counters. Open a pad's chat one minute before the slot read. 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;
   
   select slot_name, plugin, temporary, active,
          pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(), confirmed_flush_lsn)) as lag
   from pg_replication_slots;
   
   show logical_decoding_work_mem;

   Read the result like this:

   • 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 at or above 1,000 ms: record it as a spike on the current row, and do step 3. The 2026-10-25 read gave 14,561.2 ms, so this branch applies.
   • 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] Watch with option A, then start a 7-day window. Option A is the per-query reset (ruling 2026-10-24). It clears only the current list_changes row, so its max_exec_time starts from 0. It is one write to prod. It erases that row's lifetime totals, and no other row changes. Use option B (no reset, read the lifetime max) only if the reset fails with a permission error. B is weak: a new spike shows only if it beats 14,959 ms.

   Do these in order:

   • Push the invoker-RPC migration (Revoke anon and public EXECUTE on three invoker notification RPCs #755) first, and wait for its clean 24 h GlitchTip read. No db push may fall inside the window.

   • Run the step 2 list_changes query twice, 5 minutes apart. Reset the row whose calls grows. If it is not -937396806128081, use the new id in steps 4, 5 and Verification, and note it here.

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

   • The Ship and measure the cron-health sampling change #323 one-hour measurement is done (2026-11-07), so it cannot overlap the reset.

   • Run the reset on the same day the Measure prod memory, swap and CPU for 7 days before any compute change #324 window starts. Post the UTC start and the planned end. Upgrade Supabase Postgres from 15.8.1.073 to 17 #322 runs only after the end.

   • 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 Supabase Postgres from 15.8.1.073 to 17 #322), a compute change, a project restart or a db push. If one happens, restart the window.

5. [maintainer] Read the rows once a day for 7 days. Read at about 05:00 UTC, after job 37's daily run at 04:15. Open a pad's chat one minute before the slot read. Add one row per day to a table in this issue. Record calls, total_exec_time and max_exec_time per row. If a new queryid appears, add it to the table.

   select now(), queryid, calls,
          round(total_exec_time::numeric, 1) as total_ms,
          round(max_exec_time::numeric, 1) as max_ms
   from pg_stat_statements
   where query ilike '%realtime.list_changes%' and calls > 0
   order by calls desc;
   
   select slot_name, plugin, temporary, active,
          pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(), confirmed_flush_lsn)) as lag
   from pg_replication_slots;
   
   select slot_name, spill_txns, pg_size_pretty(spill_bytes) as spill
   from pg_stat_replication_slots;

   max_exec_time is the running max since the reset. A day is a spike day when it rose since the day before and is now 1,000 ms or more. The daily mean is (total ms delta) / (calls delta) between two reads. The daily read puts any spike inside one 24-hour span.

5b. [maintainer] Optional: time chat delivery. On day 0 and day 7, create a scratch pad you own, and send 10 chat messages on it. Time send to receive in a second browser. Report median and range. Delete the scratch pad after. Keep this out of the pass rule.

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 spike day	Close. Record "the 14,561.2 ms spike came between 2026-09-28 and 2026-10-25; cause unknown; none in the window".
   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 Supabase Postgres from 15.8.1.073 to 17 #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 counters pasted, or "no slot present at read time" with the UTC time. logical_decoding_work_mem and stats_reset are pasted.
• Realtime logs for job 37's first-run hour were searched, and the finding (or "nothing logged") is recorded.
• 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, restart or db push.
• The outcome row from step 7 is recorded. Any follow-up issue is linked.
• No full pg_stat_statements_reset() was run.
• Benchmark table filled.

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 in the first hour are within 50 % of the hourly rate read just before the reset, and max_exec_time is 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 the live row stays under 1,000 ms, and the daily 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.