mars
MARS-661
Connection churn: CPU framing disproven, latency question open (get_auth 3.6ms mean / 24ms stddev)
Canceled low
unassigned
Split out of MARS-658 after measuring. Over the 72-day pg_stat_statements window the two largest entries in the WHOLE database are connection establishment, not queries: pgbouncer.get_auth 667,658 calls / 2,426.9s / 3.6ms mean, plus the per-connection role_setting query 192,419 calls / 591.8s. Together ~3,018s — roughly 24x the entire lookup-helper layer (124s) that MARS-658 addresses, and about 5x the next single query. Not investigated yet; this WI is to investigate, not a diagnosis. Open questions: whether pg connections are being established per-request rather than pooled, whether the Vercel serverless runtime is defeating pool reuse, and whether DATABASE_URL vs DATABASE_URL_DIRECT usage differs by call path (note: DATABASE_URL_DIRECT is a Supavisor SESSION-mode pooler with a session cap). Deliberately NOT proposed as a remedy for the Supabase disk-IO depletion email — that closed as a tier-level upsell notice on measurement (mars 113MB db, 2,813 disk reads, 100.00 percent cache hit over 6 months; pluto measured the same shape independently). This is a CPU/latency item on its own merits. Next two by total_exec_time after the above, for whoever picks this up: 565.4ms mean x 657 calls and 624.7ms x 547 calls — low volume, high mean, worth their own look.
Activity
-
MEASURED THE DENOMINATOR — the CPU framing in my own description is empty. Total exec time across ALL statements is 17,613.5s over a 72.2-day window = 0.282 PERCENT OF ONE CORE. get_auth is 13.8% of DB time and connection setup together 17.2%, so eliminating churn entirely recovers ~0.05% of a core. The 24x-the-lookup-layer comparison is true and useless: both numerators sit under an idle denominator. Same shape as the disk-IO investigation that closed as a tier-upsell notice. WHAT SURVIVES, on a different axis and NOT yet measured: latency. 668,517 authentications over 72 days is 9,285/day, one every ~9s, at 3.63ms mean with a 24.19ms STDDEV — the tail is far worse than the mean. If a material share of those sit in front of a user request rather than a cron or an agent session, that is user-visible latency no CPU percentage reveals. Open with db-mars-cc: attribute connections by source — Vercel runtime pool vs 14 cron jobs vs weekly-kpi's separate DIRECT session-mode pool (max 16) vs psql/Supabase-MCP sessions from our own agents (7 mars agent .mcp.json files point at mcp.supabase.com; if agent tooling is a material share the fix is our habits, not app code). Open with audit-mars-ca: whether pct-of-one-core is the right normaliser at all, and whether a 24ms stddev on a 3.6ms mean justifies the latency pass before anyone measures request-side impact. App-side, unchanged and not claimed as a cause: src/lib/db.ts global pg Pool, max 6, Supavisor transaction-mode :6543, connectionTimeoutMillis 10s, pool error listener present, NO idleTimeoutMillis set so pg's 10s default applies. First suspect if the app turns out to be the source; unmeasured.
-
Connection churn: CPU framing disproven, latency question open (get_auth 3.6ms mean / 24ms stddev)
-
audit-mars-ca ruling: CPU framing downgraded/closed, WI bounded to attribution + latency measurement only. Their qualification on my own denominator, which I am recording because it narrows what I may claim: percent-of-one-core is NOT a complete Supabase-tier metric — actual vCPU quota, throttling and billed compute all matter and I measured none of them. It is sufficient to rule OUT a CPU project on an idle system; it is not sufficient to characterise the tier. Their gate on the latency hypothesis, which I accept: 3.6ms mean + 24.2ms stddev is INSUFFICIENT on its own. Required order, no work before it: (1) attribute auth calls by source [db-mars-cc, outstanding]; (2) measure request-side p50/p95/p99; (3) establish whether connection setup is on the critical path at all. Only then does any app change get proposed. Nothing to implement. No commit exists or is planned for this WI in its current state.
-
3
-
Blocked on a read with no queryable path. db-mars-cc established (read-only) that attribution is IMPOSSIBLE from inside Postgres: get_auth is Supavisor's own auth_query mechanism, firing when the pooler opens/reopens a PHYSICAL connection to Postgres — not once per app request. Confirmed via pg_stat_activity: the only session tagged application_name='Supavisor (auth_query)' runs as role pgbouncer with backend_start 2026-08-09, a single long-lived session. The two role_setting queries are the same mechanism's config-fetch companions, same caller. Supavisor authenticates ITSELF to Postgres, so the identity of the end client that caused a given connection cycle is not visible from inside Postgres at any privilege level. query_logs caps at 24h and cannot reconstruct a 72-day window. ONE CANDIDATE ELIMINATED STRUCTURALLY: pg_cron jobs run as in-process background workers, not network clients, so they never traverse Supavisor and cannot drive get_auth. All 13 active cron jobs are out. Remaining candidates — Vercel runtime pool, weekly-kpi's DIRECT session-mode pool, agent psql/Supabase-MCP sessions — are indistinguishable from Postgres-side introspection. CONSEQUENCE FOR AUDIT'S GATE: audit required attribution BEFORE any latency work. That step is now known-unavailable by the route we were taking, so the WI cannot proceed on Postgres introspection alone. The only remaining source is Supavisor's own pooler metrics (Supabase dashboard -> Database -> Connection Pooling), which is outside db-mars-cc's query surface and is a dashboard-only read with NO queryable path — the exact class covered by mars-unverifiable-state.md. Not proceeding on assumption. The CPU framing stays disproven (0.282% of one core); the latency hypothesis stays UNTESTED rather than dismissed.
-
THREE-PROJECT COMPARISON, all measured by the owning db lanes, windows stated: pluto idleTimeoutMillis=5s get_auth share 18.5% mean 2.32ms duty 0.120% of one core (66.8d window) mars idleTimeoutMillis=10s (pg default) 13.8% mean 3.63ms duty 0.282% (72.2d) venus idleTimeoutMillis=30s 6.67% mean 0.53ms duty 0.052% (109d) Share is MONOTONIC with idle timeout across all three (5s > 10s > 30s -> 18.5 > 13.8 > 6.67). Three datapoints, zero experiments, confounded by traffic volume — a hypothesis with support, not a result. Per-call cost is the one real difference (venus 0.53ms vs mars 3.6ms, ~7x) and it is not a share artefact. UNCHANGED: nothing to fix in absolute terms; all three sit on idle databases. Unanimous across coder-pluto-cc, coder-venus-cc, audit-mars-ca, db-mars-cc: do not touch a live pool on an unmeasurable hypothesis. THE ONE CHEAP DECISIVE TEST if Elazar wants it settled rather than argued (coder-venus-cc's framing): set idleTimeoutMillis=30_000 on Mars (matching venus), pg_stat_statements_reset(), re-read get_auth calls/day after ~7 days. One variable, measurable, reversible. Not doing it without a GO — it is a change to a live pool.
-
Cancelled per Elazar 2026-08-24 (nqla 4a). Reason: NO READ PATH, not scope-obsolete and NOT 'harmless'. The investigation is preserved in mars/shared/md/mars-unverifiable-state.md under 'Supavisor pooler connection metrics', owner coder-mars-cc, which is where load-bearing state with no queryable read path belongs per evolutiva-commons.md. A blocked WI is not a record - it looks like queued work forever and can never unblock, which is exactly the failure mode evolutiva-commons.md §Scaffold-Time Retirement Check names for the backlog surface. CARRIED INTO THE RECORD AND MUST NOT BE LOST: the CPU framing is DISPROVEN (0.282% of one core); the LATENCY hypothesis is UNTESTED, not dismissed. Do not let this cancel be read as 'connection churn was found harmless' - it was found UNATTRIBUTABLE. db-mars-cc established read-only that Supavisor authenticates ITSELF to Postgres, so the end client behind a given connection cycle is invisible at any privilege level; pg_cron is eliminated structurally (in-process workers never traverse the pooler, all 13 jobs out). Reopens if a Supavisor pooler-metrics read becomes available to this lane.
-
BACKFILL written 2026-09-02 by coder-basquetwi-cc, authorized by the owning lane. Historical repair for the bug fixed in 526f6b0: closing a BLOCKED row directly to a closed status wrote only the 'unblocked' event and never the terminal one, and the close reason landed on that unblock event. The row was always correctly closed (closedAt stamped, questions closed, status correct); only the ledger was wrong, and its last word read 'unblocked' - which reads as still-open to anyone reconciling by event rather than by status. THIS EVENT IS NOT CONTEMPORANEOUS: its timestamp is the repair's write time, not the real close time, which is in closedAt. The original close reason has been left where the bug put it, on the unblock event, deliberately - it is the only artifact showing the bug's shape. Note: this row is a CANCELLATION, not a completion - Elazar cancelled it 2026-08-24 for NO READ PATH, explicitly not scope-obsolete and not harmless. A 'completed' event here would assert the work was done, which is the opposite of what happened. Distinction confirmed by coder-mars-cc before this backfill was written.
task
7w ago by wi-cli-venus
7w ago
2026-08-24 14:16