Supabase instance-level slowness 2026-09-11 22:34Z - 2026-09-12 01:54Z (3h20m continuous): 42 slow queries incl. 'SELECT now()' at 35s, AT LEAST 4 user-facing 500s on /mi-cursada (3 logged + 1 whose own serverError INSERT left no row), one operator alert LOST
RE-OPENED 2026-09-12 on the criterion this row carried at close ("re-open only if the same shape recurs - that would make it a rate, not a window"). It recurred, and BOTH the span and the cause on the closed version were wrong. The benign reading rested on two instruments - /api/health dbOk true at 22:40:19Z and 22:48:19Z, and the pre-push gate passing at 22:44 - that both sampled INSIDE a still-open window. A successful sample is not the absence of failures. WHAT IT ACTUALLY WAS, measured from Supabase postgres_logs via the Management API (read-only, /v1/projects/{ref}/analytics/endpoints/logs.all, 24h retention so this was recoverable only because it was read the same night). Queries logged over the auto_explain threshold: 42 in 2026-09-11 22:00Z - 2026-09-12 02:00Z, ONE in the preceding four hours, ZERO in the following four. So the instance itself was slow, and the boundary is sharp on both sides. THE INSTANCE WAS SLOW, NOT THE NETWORK AND NOT THE APP POOL. The load-bearing entry is 00:32:52Z: "SELECT now()::text AS now" took 35650 ms. That statement touches no table, reads no page, takes no lock. A trivial query taking 35 seconds cannot be explained by a query plan, by lock contention, by pool sizing or by anything in application code - it is instance-level resource starvation. Corroborating durations in the window: INSERT INTO "appEvents" at 115005 ms, 72081 ms, 52409 ms, 46743 ms, 45547 ms, 42682 ms; SELECT "value" FROM "systemSettings" (the system-banner read that runs on render) at 40988 / 36123 / 23035 / 20213 ms and seven more over 10s. AND THAT CORRECTS THE CAUSAL CLAIM THIS ROW CARRIED ON RE-OPEN. I wrote that "authentication did not complete within 15000ms" proved POOLER-side saturation. It does not. postgres_logs shows "SELECT * FROM pgbouncer.get_auth($1)" - the pooler's OWN auth lookup against Postgres - taking 21930 / 19444 / 15614 / 13726 / 13246 / 13214 / 11053 / 10822 / 10021 ms at 22:58, 23:25, 00:35, 01:02, 01:04, 01:16, 01:33, 01:50 and 01:54. The pooler stalled because the database it authenticates against was slow. Supavisor is a victim here, not the cause, and every downstream symptom (the app's "timeout exceeded when trying to connect", the Session-mode ECHECKOUTTIMEOUT in applog-pull, my local ECONNRESET) follows from the same one fact. THE SPAN IS 22:34:20Z TO 01:54:08Z - THREE HOURS AND TWENTY MINUTES, CONTINUOUS. Not a 4-minute window, and not "22:33-23:19 with a trailing blip at 01:50": the slow-query log has entries in essentially every 10-minute bucket across the whole span. The appEvents rail looked quiet between 00:48Z and 01:53Z because the app could barely write to it - a 115-second INSERT INTO "appEvents" at 23:21:06Z is the telemetry rail itself being throttled. Absence of rows there was a symptom, not silence. IT REACHED USERS THREE TIMES, not once. db-pluto-cc (prod appEvents, SELECT only, 22:00Z-02:00Z, 31 rows total in 7 groups): error/serverError on /mi-cursada x3, first 22:57:03.083624 and last 01:53:30.275983 (the middle one's timestamp was not asked for) - all three share digest 2097667694, all appVersion 2.23.95, all actorUserId NULL. One fault, three renders, no signed-in actor on any. Also in the window: warn/systemBannerQueryFailed x10 (22:33:35.773092 -> 00:48:00.682241), info/email-sent x10, info/applogListenerHeartbeat x4, info/page_not_found x2, error/operatorAlertTimeoutFallback x1, info/login x1. That is the whole window - so the rate IS now stateable: 31 appEvents rows / 4h, of which 4 are error. WATERMARK, resolved: the applog-pull watermark froze at 00:48:00.682241+00, which is EXACTLY the max createdAt of systemBannerQueryFailed - it froze ON the last row of the dominant action, it did not drift. Rows that exist after it and were never pulled: 2 page_not_found at 00:55:13/00:55:15 and the serverError at 01:53:30. Three rows, all after. FALLBACK ALERT LOST - see PLUTO-688. error/operatorAlertTimeoutFallback at 23:19:06.958036Z (id 76521be1-f902-4985-9e98-cdfc581dcb51) is the PLUTO-688 give-up path firing in production for the FIRST TIME EVER, and its detail reads outcome=enqueue_failed, attemptMs=3500, budgetMs=8000. The durable fallback could not enqueue because the enqueue needs Postgres and Postgres was the thing that was slow - exactly the bound operator-alert-leg.ts:110-112 states in source, realised rather than hypothesised. CAVEAT ON ANY WRITE-UP: detail.serverErrorEventId is a PRESENT KEY WITH A NULL VALUE, so that row cannot be joined to the serverError it was alerting about, by id or by time (nearest is 22:57:03Z, 22 minutes earlier). "This fallback is for 45b662e6" is an inference, not a link. NOT THE PLUTO-511 PUSH, and the ordering is what proves it rather than the "two network paths, same instance" argument the closed version used - that argument is equally consistent with the pre-push gate consuming pooler slots. First failure 22:33:35Z, BEFORE the push511b gate started (~22:35); failures continue to 01:54, more than three hours after "main -> main" landed at 22:44. WHAT IS STILL OPEN. The Supabase-side cause is narrowed to instance resource starvation but not named. Two facts point at undersizing rather than a one-off: the current metrics scrape shows node_memory_MemAvailable ~258 MB, and cumulative node_cpu_seconds iowait (351148s/CPU) EXCEEDS user+system combined (189k+97k) over the instance lifetime - an IO-bound instance with almost no page cache. Both are CUMULATIVE counters and a point-in-time scrape, so neither can be attributed to this window; they are a reason to look, not a measurement of the incident. Disk is not the constraint (gp3, 8 GB, 3000 IOPS, 125 MiB/s provisioned, 6% used). Per-window CPU/IO/memory charts are dashboard-only - the Management API exposes only an instantaneous Prometheus scrape - so that read needs Elazar's hands, and the remedy if it is undersizing costs money. Escalated by eq rather than decided here. Related: [[pluto-708-supabase-disk-io-budget-alert]], the free-tier IO upsell already on file, and eq#88 (Session-mode pooler under load), for which this is the first field evidence. QUIET SINCE: zero slow queries after 01:54:08Z through 05:55Z; every 30-minute applog-pull clean since 02:20Z; five /api/health samples at 05:46-05:47Z all dbOk true at 0.35-0.93s.
Activity
-
Benign, self-resolved, closed on filing. Two instruments agree the window ended: /api/health dbOk true at 22:40:19Z and 22:48:19Z, and the identical pre-push gate that died at 22:36 passed at 22:44 with 932 tests. Re-open only if the same shape recurs - that would make it a rate, not a window.
-
RE-OPENED on the criterion written onto this row at close: 'Re-open only if the same shape recurs - that would make it a rate, not a window.' It recurred. Six further alerts after the close, spanning 43 more minutes plus a trailing failure 3 hours later.
-
2
-
applog: recurring Supabase connect/auth failures 2026-09-11 22:33Z-23:19Z + 01:50Z - reached a user-facing route, NOT a benign window
-
was: applog paged a cluster of DB-connect failures in a ~4 minute window on 2026-09-11: systemBannerQueryFailed 'authentication did not complete within 15000ms' at 22:33:35Z (6a6f991a) and 22:33:52Z (b255244d), then three 'timeout exceeded when trying to connect' at 22:36:57Z, 22:37:14Z and 22:37:26Z, all route __no_route__. TRIAGE, same turn: NOT an app defect and not caused by the PLUTO-511 push. Independent corroboration from a second host - my local .gitpush-pre.sh run failed at 22:36:08 ART with ECONNRESET out of pg-pool (generate-intake-pdf.mjs getLookups, 'Client network socket disconnected before secure TLS connection was established'), so venus-local and Vercel-runtime were failing to reach the same Supabase instance in the same window over two different network paths. That is an upstream connect/auth window, not a pool-sizing or query defect - the failures are at CONNECT, before any statement runs, which is the distinction [[pluto-cold-connection-establishment-not-query-slowness]] exists for. RESOLVED WITHOUT ACTION: /api/health read dbOk true at 22:40:19Z and again at 22:48:19Z, and the identical gitpush run succeeded on retry at 22:44 with 932 tests green, so the window closed on its own. Closed benign with the evidence on the row rather than left open as an unexplained page. WHAT WAS NOT DONE: no appEvents read (prod DB reads go through db-pluto-cc, SELECT only) so the row count in the window is the five applog paged, not a measured total; and no Supabase-side status check for the window.
-
operatorAlertTimeoutFallback at 23:19:06Z is the PLUTO-688 fallback path (operator-alert-leg.ts:154, written only after the alert budget times out). First firing in prod since 1c21d0b on 2026-08-22, and it fired because the DB was unreachable - the one case that path cannot close, since the enqueue needs the DB too. Correction filed on PLUTO-688; the 'zero fallback rows all-time' premise there is now false.
-
was: RE-OPENED 2026-09-12 on the criterion this row carried at close ("re-open only if the same shape recurs - that would make it a rate, not a window"). It recurred, and the close was wrong in its verdict, not only in its span: the benign reading rested on two instruments (/api/health dbOk true at 22:40:19Z and 22:48:19Z, and the pre-push gate passing at 22:44) that both sampled INSIDE a still-open window. A successful sample is not the absence of failures. MEASURED TIMELINE, all UTC, 2026-09-11 unless stated. 22:33:35 and 22:33:52 systemBannerQueryFailed "authentication did not complete within 15000ms" (6a6f991a, b255244d), route __no_route__. 22:36:08 ART-local: my .gitpush-pre.sh run on venus died ECONNRESET out of pg-pool (generate-intake-pdf.mjs getLookups, "Client network socket disconnected before secure TLS connection was established"). 22:36:57 / 22:37:14 / 22:37:26 "timeout exceeded when trying to connect". 22:50:20 applog-pull@pluto.service FATAL "(ECHECKOUTTIMEOUT) unable to check out connection from the pool after 15000ms in Session mode" (pg-pool@3.14.0 index.js:45, applog-pull.ts:422, severity FATAL code XX000). 22:54:47 warn. 22:57:03 ERROR, and this is the one that changes the class of the row: "timeout exceeded when trying to connect /mi-cursada (system/serverError) @2026-09-11T22:57:03.083624+00:00 id=45b662e6-863b-4af5-ade3-3451fdf0ef40" - a USER-FACING route, not __no_route__ and not a background job. 22:57:14 duplicate suppressed. 23:05:39 warn. 23:19:06 email/operatorAlertTimeoutFallback on /mi-cursada (see the PLUTO-688 correction below), plus a second pull failure suppressed by the 900s failnotify cooldown. Then 2026-09-12 01:50:32 a further applog-pull FATAL with the identical ECHECKOUTTIMEOUT signature. SO THE SPAN IS 22:33:35Z to 23:19:06Z with a trailing recurrence at 01:50:32Z, not 22:33-22:37Z, and it produced at least one user-visible 500. WHY IT IS NOT THE PLUTO-511 PUSH, stated with the evidence that actually discriminates and NOT with the "two network paths, same instance" argument the closed version used - that argument is equally consistent with the pre-push gate itself consuming pooler slots, so it proves nothing. What settles it is ORDERING: the first failure is 22:33:35Z, BEFORE the push511b gate started (~22:35), and failures continue past 00:48Z, roughly two hours after "main -> main" landed at 22:44. THE DISCRIMINATING ARTIFACT IS THE 22:33 STRING, not the timeouts. "authentication did not complete within 15000ms" means the TCP connection REACHED the pooler and authentication stalled there - that is pooler-side saturation, not a network partition and not app-side pool sizing. The later "timeout exceeded when trying to connect", the Session-mode ECHECKOUTTIMEOUT in applog-pull and the local ECONNRESET are all downstream of that same condition. Leading hypothesis, NOT a conclusion: Supabase IO-budget throttling in the window, given [[pluto-708-supabase-disk-io-budget-alert]] and the free-tier IO upsell already on file. A read-only Supabase metrics read for 22:00Z-02:00Z would discriminate it; if that needs dashboard hands it goes to Elazar via eq, it does not block this row. TIES TO eq#88 (open, unscheduled): the Session-mode checkout-timeout signature is exactly the under-load pooler question that row holds. This incident is the first field evidence for it. COVERAGE STATEMENT. Quiet since 02:20Z: every 30-minute applog-pull since has finished clean, each reporting "no new warn events since 2026-09-12 00:48:00.682241+00" - the watermark is frozen at that timestamp, which also proves there were warn rows between 23:19Z and 00:48Z that were pulled but never paged. Five /api/health samples at 05:46-05:47Z all read dbOk true at 0.35-0.93s. NOT MEASURED, so the row must not be read as carrying a rate: no appEvents read was done (prod DB reads go through db-pluto-cc, SELECT only), so every count above is ALERTS PAGED, not rows; applog suppressed 4 then 1, and the failnotify 900s cooldown swallowed at least one more, so the true count is strictly higher than what is listed. No Supabase-side status or metrics read for the window either.
-
1
-
Supabase instance-level slowness 2026-09-11 22:34Z - 2026-09-12 01:54Z (3h20m continuous): 42 slow queries incl. 'SELECT now()' at 35s, 3 user-facing 500s on /mi-cursada, one operator alert LOST
-
eq#112 - the remaining work is a per-window CPU/IO/memory read that the Management API cannot serve (instantaneous cumulative Prometheus scrape only); it is dashboard-only and needs Elazar's hands, and the remedy if it is undersizing spends money. Waiting on a person, not on work.
-
Supabase instance-level slowness 2026-09-11 22:34Z - 2026-09-12 01:54Z (3h20m continuous): 42 slow queries incl. 'SELECT now()' at 35s, AT LEAST 4 user-facing 500s on /mi-cursada (3 logged + 1 whose own serverError INSERT left no row), one operator alert LOST
-
CORRECTION TO THIS ROW: "three user-facing 500s" IS AN UNDERCOUNT. The title now reads AT LEAST 4. Measured by db-pluto-cc (prod appEvents, SELECT only) 2026-09-12. WHAT PROMPTED THE RE-COUNT. The operatorAlertTimeoutFallback row at 23:19:06.958036Z carries detail.serverErrorEventId NULL. logger.ts:98-102 makes level=error isCritical, and the isCritical branch returns the RETURNING "id" on success - so a null there proves the app never got an id back, and that has exactly two readings: the row never landed, or it landed and the client lost the ack. Those give different counts, so it had to be asked rather than assumed. BRANCH ANSWERED: THE ROW NEVER LANDED. Zero serverError rows within +/-60s of 23:19:06.958036Z; nearest either side are 22:57:14.530651 (-21m52s) and 01:53:30.275983 (+2h34m). Widened to +/-5min across ALL actions and levels, appEvents holds exactly two rows in that band - the fallback itself, and warn/systemBannerQueryFailed at 23:19:06.956567 (c4764239-d7e8-42bf-8a11-757ead9acc11, route NULL). So there was a 500 at 23:19:06 that the alert leg fired for and that appEvents has no record of. Three logged plus that one is four, and four is a FLOOR, not a count - any other 500 whose serverError INSERT failed the same way is equally invisible. AND THE LOST-ACK READING IS DEAD, which matters for PLUTO-743: a lost ack loses the id, not the row. A committed INSERT would still be in the table today and it is not there, at any time, under any route. The 7 "connection to client lost" FATALs in the window can explain a null return on a row that EXISTS; they cannot explain a row that does not. THE SHARP ONE, AND IT CUTS AGAINST THIS ROW'S OWN "THE DB WAS UNREACHABLE" FRAMING: the warn row committed 1.5 ms BEFORE the fallback row, and the fallback row committed. Postgres accepted two writes from that same invocation inside the same 2 ms window in which the serverError INSERT produced no id. At 23:19:06.9 the database was reachable and appEvents was writable. Whatever killed that INSERT was not blanket unavailability - PLUTO-743 must not assume it was. The asymmetry that makes this measurable at all: level=warn is NOT isCritical, so systemBannerQueryFailed never needed an id back and its success shows up only as a row; the critical branch is the only one that reports its own failure, and it reported it as NULL. THE THREE LOGGED ONES, for the record, all /mi-cursada, all digest 2097667694, all appVersion 2.23.95, all actorUserId NULL: 22:57:03.083624 (45b662e6-863b-4af5-ade3-3451fdf0ef40), 22:57:14.530651 (603075b0-3f1b-491d-99bc-9ebcd0f9b0ca), 01:53:30.275983 (90c5076b-b162-406c-a123-a23253a74f78). The first two are 11.4 s apart - two renders, not one event double-logged. TWO SCOPE NOTES ON THE DESCRIPTION ABOVE, corrected here rather than by another full rewrite. (1) "entries in essentially every 10-minute bucket" overstates it - the largest gap inside the span is 23:26 to 23:50, 24 minutes. The span is still continuous at the hour scale; it is not gapless at the ten-minute scale. (2) The "ZERO in the following four hours" half of the 42-vs-1-vs-0 comparison covers 02:00-06:00Z = 23:00-03:00 ART, the day's lowest-traffic window, so it is the weaker arm. The load-comparable baseline is the PRECEDING four hours - 42 versus 1 - and that is the comparison the instance-level verdict should rest on. Recovery is evidenced independently of both by the clean 30-minute applog pulls since 02:20Z and the five sub-second /api/health samples at 05:46-05:47Z. STATUS: this row is now BLOCKED on eq#112 (per-window CPU/IO/memory is dashboard-only and the remedy spends money - Elazar's hands, not work anyone here can do).
-
EPISODE 2. THE SIGNATURE RECURRED ON 2026-09-18, AND THIS ROW'S "ONE INCIDENT" FRAMING IS DEAD. Measured by me 2026-09-19 06:30Z via the Supabase Management API logs.all endpoint (read-only, no app-table read, no DB credential). TRANSCRIBED IN FULL HERE BECAUSE THE SOURCE EXPIRES TODAY: logs.all retention is 1 day, so the 13:00Z bucket starts falling out around 13:00Z today and the whole episode is unrecoverable after ~21:00Z. Everything below is verbatim from the log store and cannot be re-derived once that passes. WHAT IT IS: A SECOND DISCRETE BOUNDED EPISODE, NOT A SUSTAINED RATE. Window 2026-09-18T13:00Z-21:00Z (10:00-18:00 ART). Slow queries (duration: lines) bucket 14Z:4 15Z:3 16Z:14 17Z:10 18Z:8 19Z:6 20Z:4 = 49, with ZERO in 07-13Z and ZERO in 21Z-06:30Z; first at 14:25:29, last at 20:09:53, clean edges both sides. Statement-timeout cancels bucket 13Z:12 14Z:11 15Z:14 16Z:21 17Z:12 18Z:12 19Z:12 20Z:3 = 97, co-located and peaking in the SAME hour (16Z). Also in-window: FATAL 25 ("connection to client lost"), the same FATAL shape episode 1 carried. MAGNITUDE: RECURRENCE AT COMPARABLE MAGNITUDE - NOT WORSE, AND THE "WORSE" READING IS WRONG. 49 over ~6h is 8.2/h against episode 1's 42 over 4h = 10.5/h, i.e. LOWER. The 97 timeouts have NO episode-1 baseline and never will: the 2026-09-11/12 window is past retention, so that arm is permanently uncomparable and must not be added to the 49 to manufacture a larger number. NO LOAD OR TIME-OF-DAY CORRELATION - STATED EXPLICITLY SO NOBODY RE-DERIVES IT. Episode 2 ran 13-21Z = 10:00-18:00 ART. Episode 1 ran ~22Z-02Z = ~19:00-23:00 ART. Different times of day, so the two do not share a traffic-shape or scheduled-job explanation on the face of it. THE ARTIFACT THAT KILLS EVERY APP-SIDE CAUSE, and it is stronger than episode 1's: SELECT 1 at 20964.052 ms (15:43:20). No function call, no cast, no catalog lookup, no table page, no lock. SELECT now()::text at 10456.357 ms (14:43:56) says the same thing more weakly. Nothing in src/ can make SELECT 1 take 21 seconds. REPEAT-VICTIM SHAPES, verbatim. systemSettings banner read (SELECT "value" FROM "systemSettings" WHERE "key" = $1, $1='banner'), FIVE occurrences: 80515.327 ms (16:27:41), 50540.781 (18:24:19), 31301.323 (20:04:01), 28123.639 (19:26:42), 19983.194 (18:24:19). INSERT INTO "appEvents", THIRTEEN: 89639.550 (19:22:39), 88519.089 (17:22:54), 81636.404 (17:29:34), 80937.437 (19:21:13), 76978.513 (17:14:30), 72007.126 (16:50:02), 43717.797 (16:34:19), 34669.739 (20:02:41), 18702.271 (16:39:04), 17845.036 (17:27:33), 15485.997 (16:34:08), 14229.636 (17:27:34), 10378.415 (17:32:36). SELECT * FROM pgbouncer.get_auth($1), FIFTEEN, 10-29 s, alternating $1='postgres' and $1='applog_reader': 28952.511 (17:21:57), 25074.153 (17:50:39), 24149.453 (17:01:16), 22250.091 (16:13:53), 19847.049 (19:55:45), 14934.653 (14:25:29), 13346.514 (18:06:35), 12767.154 (18:24:05), 12671.711 (16:57:52), 11283.048 (16:33:54), 11118.378 (18:19:26), 10886.816 (17:26:17), 10862.256 (20:01:00), 10731.169 (18:19:26), 10244.166 (16:13:54). The auth path itself is a victim - per this row's earlier finding, that is Supavisor being starved, not Supavisor saturating. Others: applog-pull appEvents SELECT at 73586.893 (16:45:20), 43187.089 (18:34:27), 23100.996 (19:59:33), 21364.155 (18:24:50), 12288.993 (20:09:53), 10402.041 (16:39:02); INSERT INTO "emailOutbox" 17872.683 (19:23:21); information_schema probes 26882.481 (14:52:34), 11659.271 (16:52:09); pg_stat_activity monitor reads 12322.232 (16:03:57), 12289.521 (16:03:20); pg_stat_statements aggregate 13512.188 (14:41:14); and two duration lines with NO query text at all, 68097.532 (15:02:30) and 18343.349 (15:06:20). ONE OBSERVATION I AM DELIBERATELY NOT USING AS EVIDENCE. The PostgREST background error schema "pg_pgrst_no_exposed_schemas" does not exist runs at a flat ~110/h and is ABSENT 14Z-19Z, which looks like corroboration that even a 33-second retry loop was starved. It is not usable: the same series is also absent 23Z-06:30Z, a 7-hour gap with no incident to explain it. A series with an unexplained quiet period is not a presence instrument, so its silence during the episode proves nothing either way. Recorded so it is not re-picked-up as support later. CONSEQUENCE FOR PLUTO-743, which was previously motivated by one episode. appEvents INSERT reached 89639 ms inside a window carrying 97 statement-timeout cancels, so episode-2 serverError INSERTs plausibly failed exactly the way the 23:19:06 one did in episode 1. The episode-2 user-facing 500 count is therefore also a FLOOR, and minting the appEvents id app-side is now motivated by TWO episodes. Noted on 743. RECOVERY, as a coverage statement rather than an all-clear: last slow query 20:09:53Z, nothing in 21:00Z-06:30Z on the slow-query or timeout instrument, /api/health dbOk true at 06:17:57Z (version 2.23.96, dpl_Vn74q6Kxqvz8zjATaqxdKgPHywNY). That is ~10 hours quiet INSIDE THE LOG WINDOW ONLY - retention is 1 day, so nothing here speaks to 2026-09-13 through 2026-09-17, and the true inter-episode interval is unknown rather than 19 hours. STATUS UNCHANGED: still BLOCKED on eq#112. The remedy is still a compute-spend decision on a free-plan project and per-window CPU/IO/memory is still dashboard-only. What changed is the argument for it: eq#112 carried my line "one incident, no recurrence in the seven days since", which I wrote without checking and which is FALSE. Corrected on that row in the same turn as this event.