get_practica_detail_bundle: fixed per-call planning of vPracticaHistorial puts the tail on the 10s cap, cancelling /mi-cursada under mild stalls
USER-FACING: students reloading /mi-cursada/[id] into repeated 'canceling statement due to statement timeout' errors. Burst 2026-09-20 13:05:06-13:05:35Z, v2.79.81. WHAT USERS SEE: 12 appEvents rows in 27s (category=server, action=unhandled-server-error, renderSource=react-server-components-payload). 8 on routePath /mi-cursada/[id] for practica e465be99-a90a-4380-a766-359de680ca75, 4 on the /mi-cursada list. The _rsc token rni7rOKCZJbbE_eD repeats on 6 of the 8 detail rows, so this is ONE navigation retried, not 12 users - a student reloading a course page into a failing query for half a minute. Prior clusters: 09-19 15:00Z, 09-18 01:00Z, 09-16 23:00Z and 18:00Z, so this recurs. DB SIDE (db-mars-cc, read-only, postgres_logs): 16 cancelled statements in the window, all role mars_app_runtime - 9x 'SELECT changelog,reviews,comentarios FROM get_practica_detail_bundle($1)' plus an unreadCount/ladder query, a practica list, a vp detail, a periodos/comisiones list and 2 with empty text. Bundle-dominated but MIXED: the trivial reads are collateral cancels in the same stall, not independent failures. PostgREST heartbeat 13:04:56 -> 13:05:41 (45s vs ~33s) = mild stall. Checkpoint 13:03:33 (46 buffers, write=4.8s) began before the cancels. WHY THE BUNDLE IS ALWAYS FIRST TO DIE: pg_stat_statements for get_practica_detail_bundle = 1963 calls, mean 578ms, stddev 1057ms, MAX 9922ms against a 10s runtime cap, ~820 buffer hits/call. The tail ALREADY sits on the timeout with no stall at all, so mild slowness is sufficient to cancel it rather than required. ROOT CAUSE, measured by EXPLAIN on e465be99 (as postgres, warm, NO 10s cap - not runtime parity): whole bundle 330ms exec, 3339 buffer hits, 0 reads. The changelog sub-select alone (vPracticaHistorial for that id) is 20.6ms exec but 93ms PLANNING with 1490 planning buffer hits. The cost is mostly FIXED PER-CALL PLANNING of vPracticaHistorial - a UNION across practicas/teeth/images/conductos archive arms, ~40 joins - not data volume: this practica has 8 history rows. That fixed cost is paid on every call for every practica, is CPU-bound, and stretches under any slowness. CANDIDATE FIXES (db-mars-cc, none applied, code/DB lane to choose): make the function plpgsql or otherwise plan-cached so the plan is not rebuilt per call; or slim vPracticaHistorial. NOT VERIFIED: how much of the 330ms is the comentarios sub-select (not isolated); that planning is the tail driver under runtime conditions (db-mars-cc cannot run as mars_app_runtime); which other practica ids are slow. ROUTING NOTE: db-mars-cc addressed this to coder-mars-ca, which is NOT on the hub roster - the 2026-09-19 handoff named it but no such agent exists. coder-mars-cc is live and took the MARS-677 relay today, so it is assigned here.
Sub-tickets — 0/1 done
Activity
-
707b04c (v2.79.82) live: /api/health 2.79.82 == remote package.json, dpl_2VN4CL7CDA5p6j3FmtU2NPsNGAHV, runtime error/fatal 10m: none. Publishes db-mars-cc aec62c0 (migration 166 plpgsql), audit-general-cc PASS:aec62c0 static (applied md5(prosrc) == file; root 165-167 collision is naming only). The DB change has been live since apply 09-20 ~13:12Z; the deploy only published the file. Acceptance still open: post-deploy pg_stat_statements vs baseline calls 1963 / mean 578ms / max 9922ms; regression = revert to mig 121 body. Tail fix UNPROVEN.
-
2026-09-20 23:21-23:22Z, v2.79.82 with migration 166 live: 3 x 57014 on /mi-cursada/261c266b-2cd3-455f-95f7-97c7517fc654 inside PL/pgSQL get_practica_detail_bundle (digest 490346572, fingerprint 071bec33, Vercel runtime log). Same practica repeated within 5s => data-shaped exec cost for that id, not planning. Plpgsql change did NOT prevent it; tail fix remains unproven/negative for this id. Asked db-mars-cc for per-arm EXPLAIN ANALYZE on that id. Class profile from support-evolutiva-cc: 55 statement-timeout rows / 14d, digest 490346572 = 10 of 14 /mi-cursada/[id] rows since 09-15.
-
db-mars-cc instrumentation read 2026-09-20 23:21:30-23:24:30Z: 261c266b is not data-shaped (changelog 3.8ms, comentarios 0.2ms, warm). No lock wait logged (log_lock_waits=on; predicate never seen to match a real wait here = unvalidated zero), no autovacuum on the tables, checkpoint after the cancels. PostgREST heartbeat gap 59.7s vs ~33s across the cancel window => SHORT DB-WIDE STALL supported (CPU vs IO vs host NOT provable from here; Supabase dashboard CPU/IO/memory 23:21-23:23Z is a human read). Only get_practica_detail_bundle cancelled because it was the only work in flight. Mig 166 kept (no regression proven, not the fix). Candidate B NOT justified by this evidence, no row. Recurring root cause = platform stall, same family as MARS-698. Decision needed from Elazar: read the dashboard for that window.
-
Delta check attempted, honest result: cannot compute a clean delta vs the 2026-09-20 13:12Z baseline (calls=1963/mean=578.2ms/max=9922ms). pg_stat_statements now shows this query text under TWO queryid buckets (2748 calls/mean 651.5ms/max 9927.7ms, and a separate 28 calls/mean 355ms/max 1596ms) - the smaller bucket doesn't match the baseline's 1963 calls either, so pgss likely evicted/reset that entry independently of pg_stat_database.stats_reset (confirmed NULL, i.e. db-wide stats never reset - pgss has its own tracking). Dominant-bucket mean (651.5ms) is WORSE than the 578.2ms baseline, not better as hoped, and max is still essentially at the 9.9s ceiling. Correcting my earlier optimistic framing: this migration has NOT been shown to improve the aggregate, only the isolated warm-call timing I measured directly (13.8ms->2.2ms). Leaving open.
-
Live cancel event 2026-09-22 22:48:19-22:48:33Z, 3x on /mi-cursada + /mi-cursada/[id] (appEvents confirmed). get_practica_detail_bundle currently: 2823 calls, mean 660ms, max 9.927s -- against mars_app_runtime's actual statement_timeout=10s (role rolconfig), a ~70ms margin. Correlated with the cancels, not proven per-incident: pg_stat_statements is cumulative since reset and query_logs (Supabase analytics endpoint) is still down (same outage as 09-20/09-21, no fleet mirror), so no per-statement timing for this window is available. Reported to support-evolutiva-cc, flagged as reinforcing the open mean-regression question and worth folding into Elazar's pending Disk IO/pooler dashboard read.
-
Stopgap applied 2026-09-22 19:53 ART (support-evolutiva-cc directive, 4th user-facing cancel at 22:52:11Z): mars_app_runtime.statement_timeout 10000->20000 via ALTER ROLE, confirmed live. New connections only, not retroactive to pooled sessions. Revert: ALTER ROLE mars_app_runtime SET statement_timeout = 10000. Real fix (mig166 regression + Disk IO read) stays open on its own track, unaffected by this stopgap.
-
db-mars-cc 2026-09-23: incident windows 19:20-20:34Z (19:22Z breaker event + 20:29-20:31Z saturation event) frozen in public."stallSamplesIncident" (mig179, 10742 rows/444 run ticks, no prune). Sampler now records stateChangeAt/idleForMs (mig178, rows from 19:24Z on). mars_app_runtime statement_timeout reverted 20000->10000 per support-evolutiva-cc (20s bought nothing measurable, doubles pooler slot hold under saturation).
-
New occurrence 2026-10-10T23:12:16Z: 2 fresh statement_timeout cancels on /mi-cursada (appEvents ids 5b8b5822, 5ad199ef), same signature as the original report. Row has sat in backlog unfixed since 2026-09-20 (only a since-reverted timeout bump, no query fix). Recurring user-facing failure - escalating to active fix, not another observation note.
-
Crash-symptom fix shipped: SHA 08e9c80 (v2.85.25), PTD-verified (deploymentId tail mhmXfT5Na1eJHunCKCBtPbJgRWFu matches live /api/health; version 2.85.25 live). Added loadOrDegrade() (src/lib/load-or-degrade.ts) wrapping each Promise.all entry on /mi-cursada (prior SHA 5087c50, v2.85.24), /mi-cursada/[id] and /practicas/[id]: a statement-timeout or other query failure now returns null + logs an error-tier appEvents row instead of crashing the whole render; each page shows a visible 'no pudimos cargar...' notice for the degraded section, never a silent empty state. getPracticaDetailBundle itself stays unwrapped (self-check-registry probes it directly). CORRECTED FINDING on the 2026-10-10 23:12Z occurrence named in support-evolutiva-cc's note: both cancels (5b8b5822, 5ad199ef) hit /mi-cursada (list page's own 3-query Promise.all), NOT /mi-cursada/[id]/get_practica_detail_bundle as this row's title assumes. getStudentPracticas is well-indexed and cheap on average (pg_stat_statements: calls=2679, mean=125ms, max=5896ms) - recurring risk is platform-stall-driven, same family as MARS-698/769, not a query-shape defect on that path. The bundle/vPracticaHistorial planning-cost theory (this row's original subject) remains independently real and historically dominant for the ORIGINAL 2026-09-20 burst (8/12 events on the detail page) - fixed here for the CRASH symptom on all three call sites, but the underlying fixed per-call planning cost of vPracticaHistorial is untouched, and the 2026-09-20 decision note's ask ('read the dashboard for that window' re: platform-stall root cause) was never answered by Elazar. Recommend: close this row's CRASH-symptom scope now; if the planning-cost fix is still wanted, split a new row for it rather than reopening this one, since 3 separate occurrences map to 2 distinct mechanisms (platform stall common to both, plus the detail page's additional fixed planning-cost tax).
-
Crash symptom fixed on all 3 call sites (SHA 08e9c80, v2.85.25, PTD-verified). Root-cause for this occurrence was the list page's own Promise.all, not the bundle this row names - platform-stall tail latency itself stays open, same family as MARS-698/769; split a new row if the vPracticaHistorial planning-cost fix is still wanted.