Pool exhaustion 2026-09-04: root cause identified (compute/storage I/O stall) — app-side hardening in progress

Sub-tickets

Activity

• wi-cli-venus created · 5w ago
• wi-cli-venus audit-finding · 5w ago
  ROOT CAUSE IDENTIFIED - Supabase compute storage I/O stall, not pool exhaustion and not app code. Blackboard bb-coder-mars-cc-mtnvjn1c-4ykt7w, 3/4 written (audit-mars-ca dead-registered, never answered). DECISIVE EVIDENCE (db-mars-cc): the checkpoint completing 23:02:41Z wrote 4 buffers / 32KB with write=85.144s, total=93.312s. Postgres own checkpointer stalling ~85s on a trivial 32KB write is a storage-layer symptom that no client, pool or query can cause. Corroborated by auto_explain over 22:00-23:00Z: EVERY logged query ran 10-79s across unrelated tables with trivially cheap plans (cost 0.01-83, correct index/PK use throughout) - a single-row UPDATE practicas WHERE id=$1 (cost 8.30) took 26.6s; a one-row INSERT INTO appEvents (cost 0.01) took 79.1s; Supavisor OWN internal pgbouncer.get_auth() stalled 17-20s. Uniform cross-table cross-workload slowness with correct plans rules out query, plan, index and app cause. max_connections=60; the 19-connection sample was 32%. log_connections was already on for the whole 21:50-00:10Z window: ZERO 'too many clients already' / FATAL entries. Postgres connection cap was NEVER breached. Pool exhaustion was never about too many connections EXISTING - it was connections HELD too long by a stalled storage layer. RESOLVES the two open questions on this WI: 1. The 19-conn sample and the 90s-later zero-response blackout are ONE event, not two. The sample landed on a low-occupancy instant inside a stall already underway. The two-signature rule still holds as a rule - it just resolves to one cause here. 2. Mode divergence is queuing math, no second hypothesis needed. Session mode holds one backend for the client's whole session, so during 10-79s queries that connection is occupied throughout and new session clients queue behind it; transaction mode returns the backend per commit, so it drained as soon as the stall eased while session mode worked off an existing backlog ~45 min longer. coder-mars-ca (research leg, cited): ECHECKOUTTIMEOUT is emitted by SUPAVISOR, not by the app's client pool - Supabase's own incident reports use this exact string for Supavisor-cluster failures. So facts 1/2 establish that each mode's Supavisor handler could not obtain a backend within 15s; they never established that Postgres hit max_connections. No official source documents zero-response direct-5432 as a signature of pooler saturation. Status-page-operational does not exclude a tenant/cluster-local incident. coder02-mars-cc (app leg): /mi-cursada/[id] does not leak or fan out - peak ~3 concurrent connections per page view (layout 1 + page 2), pg.Pool.query auto-releases, withTransaction releases in finally. Both prior defects already fixed pre-09-04. MARS-680 (get_practica_detail_bundle, mean 375.8->631.9ms 08-25..08-27, Postgres-reported MAX 46.7s) is NOT the cause here - the stall hit every table uniformly - but it is a real aggravator: a call holding a Transaction-mode connection 17-47s against connectionTimeoutMillis=10000 and pool max 6 starves the other slots. Under a storage stall it gets far worse. Fix it, and add a statement_timeout below the app's checkout budget so a runaway execution fails fast and releases its slot instead of holding it for 46s. STALE DOC found in passing: src/lib/db.ts header still claims a 'brief layout.tsx:31 3-wide overlap'. layout.tsx is 2-wide / 1 real query since migration 122 folded it into get_layout_state. Cleanup, not a live bug. INSTRUMENTATION - the cheapest instrument is already free: checkpoint write-duration is in postgres_logs today. An alert on 'checkpoint complete' lines where write= exceeds a few seconds would have flagged this before any user-facing 500. auto_explain already covers query-duration outliers. The gap is that pg_stat_activity is point-in-time with no history, which is exactly why the blackout was invisible until it was happening - a 30-60s sampler logging counts by state+application_name would close it. Not built, no buy-in taken. WITHDRAWN CLAIMS, on the record: '17 long-lived listeners' (ps|grep -c counted lines; 5 units) and the '6-project shared session-mode pooler failure domain' (Supavisor pools are tenant-scoped by username ref prefix; shared hostname is a shared FRONTEND). coder-mars-ca independently reached the second: six env files on :5432 prove nothing unless they resolve to the same project ref, database and role. STILL UNKNOWN, dashboard-only: Supavisor Default Pool Size and Max Client Connections. Do not use the 2024 public plan-limit table as a current value. NOT ACTIONABLE BY US: the stall itself was Supabase-side. It cleared on its own and can return.
• wi-cli-venus audit-finding · 5w ago
  ROUND 2 (bb-coder-mars-cc-mtnvvv7h-qqil1u, 5/6 written; audit-mars-ca dead-registered, never answered). Sharpens round 1 and adds an APP-SIDE cause that round 1 missed. STRONGEST NEW EVIDENCE (db-mars-cc): every 'connection received' line in postgres_logs STOPS COLD at 22:04:31.448Z and there is not one more until the window ends at 23:00:00Z. 56 minutes, zero new connections accepted, fleet-wide - not just db-mars-cc's probe. This kills 'IPv6 path specific to one prober' outright, and resolves the two-signature rule to ONE root event seen from two sides: (a) ECHECKOUTTIMEOUT = Supavisor's already-established backends stuck 10-79s in execution, nothing free to hand out; (b) zero-TCP-response = the postmaster's accept path ALSO frozen for the same ~56 min, so even Supavisor opening a fresh backend got nothing. Read together with the 85s/32KB checkpoint, this is bigger than 'storage slow' - the instance was substantially hung. BUT - coder02-mars-cc's challenge stands and is the version that RETURNS: signature A may not be a database event at all. The app pool sets exactly two limits, max 6 and connectionTimeoutMillis 10000. There is NO statement_timeout, NO query_timeout, NO idle_in_transaction_session_timeout anywhere in src/lib. So a 46.7s get_practica_detail_bundle call (MARS-680, server-side time) holds 1 of 6 slots for 46.7s and nothing in the app can interrupt it. Six concurrent slow calls consume the pool; the seventh fails as ECHECKOUTTIMEOUT from node-pg's OWN checkout queue, requiring no cap at the pooler or Postgres. That is consistent with fact 3 (19 backend connections) AND fact 5 (/api/health?db=1 dbOk:true at 22:27:20Z between two 500s) - health runs a bare SELECT 1 and gets a server connection immediately, while the 500s queue behind app-pool slots held by long bundle calls. A healthy DB and a saturated 6-slot client pool are exactly what those two facts together look like. This recurs on a perfectly healthy Supabase, and 'cleared on its own' is fully explained on the A side by traffic dropping after 01:40Z. TWO APP DEFECTS FOUND, both new: 1. /mi-cursada/[id] calls getPracticaDetail TWICE per request, concurrently - page.tsx:21-25 generateMetadata and page.tsx:37-40 the page component. Next runs those concurrently and getPracticaDetail is NOT wrapped in React cache(), so there is no request-level dedup. True concurrent read width is one higher than MARS-672's accounting, and the extra read is of the same práctica-keyed hot row the bundle regression is on. MARS-672 missed it because it lives in a different export. 2. page.tsx:89 fire-and-forget markComentarioNotificationsRead - launched during render, never awaited, occupies a pool slot outside the request's critical path and outlives the response. Invisible to any accounting that counts awaited reads. RULED OUT, so nobody re-checks: no connection leak on the error path. withTransaction (db.ts:76-88) releases in finally. One separate flaw: the catch does a bare await client.query('ROLLBACK') with no try, so on a dead connection the ROLLBACK error REPLACES the original error in the throw - masks diagnosis, does not retain a slot. Own WI. MODE DIVERGENCE, boring and now settled: the app NEVER touches session mode. DATABASE_URL is :6543. The only session-mode DSNs are DATABASE_URL_DIRECT (weekly-kpi, max 16) and applog-pull's own. No code path lets /mi-cursada/[id] consume a session-mode slot, so facts 1 and 2 have no shared app-side cause - two independent pools whose only common resource is the backend. audit-mars-cc, adversarial, two candidates nobody had named: - MARS-661 (cancelled 2026-08-24, 11 days before this) found the two largest pg_stat_statements entries DB-wide were connection establishment, not queries: Supavisor's own pgbouncer.get_auth (667,658 calls / 2,426.9s) plus role_setting (192,419 / 591.8s), ~24x the whole lookup layer. It was cancelled as UNMEASURABLE, not harmless - get_auth is Supavisor authenticating itself, so the end client causing the cycle is invisible from inside Postgres at any privilege level. Its named-but-never-eliminated candidates are still open and still session-mode: the weekly-KPI DATABASE_URL_DIRECT pool, and ad-hoc agent psql/MCP sessions. Closing MARS-688 as unmeasurable reproduces MARS-661 exactly. - applog-pull may be a COMPOUNDING CAUSE, not just a casualty. It uses DATABASE_URL_DIRECT session mode. If its error path does not cleanly release the pg client on ECHECKOUTTIMEOUT (a known Node pg-pool shape: a failed .connect() under load can leave a slot reserved until idle-timeout), each of the 4 consecutive failed runs compounded session-mode exhaustion rather than observing it - which also fits session mode recovering ~45 min AFTER transaction mode, since it must wait out its own leaked slots. Cheap to check, unassigned. - No deploy in the window: last commit before the incident is 1a96bee, 2026-09-02 10:40Z. Rules out a deploy-triggered connection storm. db-mars-cc's reconciliation of MARS-680: a normally-sub-second function taking tens of seconds is what this stall does to EVERY query. Its own 08-30 finding (8 concurrent calls, 16.9-37.6s each) may have been an earlier milder instance of the same stall class rather than a concurrency defect - re-check MARS-680's auto_explain history against checkpoint write-duration on those dates before treating it as a separate bug. WHAT NOBODY CAN SUPPORT YET, stated so it is not laundered: there is no timestamp-level join between the 46.7s bundle executions and 22:24-22:45Z. MARS-680's max is a daily aggregate. Until someone joins bundle exec times to appEvents 43c26f80 / fb08ab44 / 256f05c9, 'MARS-680 caused the 500s' is a mechanism that fits, not a proven sequence. ACTIONS, ranked, app-side first because that is the half that recurs on a healthy DB: 1. statement_timeout on the runtime pool (-c statement_timeout=10000 on the connection string, or a per-connection SET on pool 'connect'). Highest value, bounds hold time so one slow query cannot own a slot for 46.7s. 2. Wrap getPracticaDetail in React cache() - removes the duplicate read outright. 3. Emit pool.totalCount / idleCount / waitingCount into appEvents at the moment any ECHECKOUTTIMEOUT is caught. Today we cannot distinguish 'our 6 slots were full' from 'the pooler refused us', and that distinction is the entire argument. 4. Await or move markComentarioNotificationsRead out of the render path. 5. Read applog-pull's pg client teardown on the error path. 6. Alert on postgres_logs 'checkpoint complete' where write= exceeds a few seconds - free today, would have fired before any user-facing 500. 7. External 30-60s liveness probe: fresh TCP connect + SELECT 1, log pass/fail with latency, both pooler ports and direct. pg_stat_activity cannot observe 'cannot connect' from inside. coder02-mars-cc claims 1, 2 and 4. pm-mars-cc's leg proposes db-mars-cc extend the existing dbperf collector for 3/7 with a systemd OnFailure trigger on applog-pull@mars.service - one owner, not two.
• wi-cli-venus titleChanged · 5w ago
  Pool exhaustion 2026-09-04: root cause identified (compute/storage I/O stall) — app-side hardening in progress
• wi-cli-venus progress · 5w ago
  Action item 1 (statement_timeout) SHIPPED: mars_app_runtime role provisioned + statement_timeout=10000 scoped to it, split from postgres so db-mars-cc's own admin connection is unaffected (migration 127 df37d98, function-grant fixup 128 f573b38 after audit-mars-ca BLOCK on an overbroad EXECUTE grant, PASS:f573b38 deep). Tracked/closed as MARS-692. coder-mars-cc repointing DATABASE_URL, verification in progress on their side. Remaining action items (React cache() dedup, pool-count instrumentation, applog-pull teardown check, checkpoint-write alert, liveness probe, circuit breaker) untouched by this update.
• wi-cli-venus completed · 5w ago
  Root cause identified; nothing further actionable on this WI. The 2026-09-04 outage was a Supabase-side compute/storage stall: postgres accepted ZERO new connections 22:04:31.448Z-23:00:00Z (56 min, fleet-wide, not one prober's path), a checkpoint wrote 4 buffers / 32KB with write=85.144s, and every auto_explain-logged query ran 10-79s on trivially cheap plans across unrelated tables - including Supavisor's own pgbouncer.get_auth(). max_connections=60 with a 19-connection peak and zero 'too many clients' entries all window, so no connection cap was ever breached. Both observed signatures resolve to that one event: ECHECKOUTTIMEOUT = Supavisor's established backends stuck in execution with nothing free to hand out; zero-TCP-response = the postmaster's accept path frozen in the same window. The session/transaction mode divergence is queuing math, not a second fault. The app pool was NEVER the constraint, and this is the correction that matters most for anyone reading this later: the error string reads 'after 15000ms' while our connectionTimeoutMillis is 10000, ECHECKOUTTIMEOUT appears nowhere in our installed dependency tree, and pg-pool 3.14.0 emits 'timeout exceeded when trying to connect' instead. All three markers are Supavisor's. The discriminator sat in the error text from the first hour. Two claims withdrawn on the record: '17 long-lived listeners' (ps|grep -c counted lines; 5 units) and the '6-project shared session-mode pooler failure domain' (Supavisor pools are tenant-scoped by username ref prefix). Follow-on work is tracked elsewhere and NOT closed by this: MARS-689 (nested pool checkout deadlock - shipped c86af65, currently BLOCKed by audit-mars-ca on three findings), MARS-690 (write-path consolidation, PARKED by Elazar), MARS-691 (measure the connection-layer fixes from 2026-09-09, and the free checkpoint-write-duration alert that would have fired before any user-facing 500). The stall itself was Supabase-side, cleared on its own, and can return.