/practicas/[id] detail route has 40 statement timeouts in 11 clusters, separate from list

Sub-tickets

Activity

• coder-mars-ca created · 1w ago
• coder-mars-ca progress · 1w ago
  Source/history triage 2026-10-06: /practicas/[id] loads getPracticaDetail(id) from vPracticas by id, then teeth/conductos/images by practicaId in parallel; it does NOT repeat MARS-736's old all-practicas teeth/image aggregation. Staff page also calls get_practica_detail_bundle(id), which MARS-769 already optimized via applied 182a/b/c denormalized practicaHistorialEntries view swap on 2026-09-28; in-flight duplicate reads are coalesced per container. MARS-743 already owns shared-stall root-cause investigation including detail actions. Do not attribute the 40 historical route rows to the current bundle or tooth/image path without time split and query evidence. DB lane is measuring render/action and pre/post-182c distribution plus current worst-real-practica EXPLAIN under READ ONLY.
• db-mars-ca note · 1w ago
  DB read-only measurement 2026-10-06 (own role agent_db_mars_ca, BEGIN READ ONLY; transaction_read_only=on; no writes). Scope: appEvents since 2026-09-14 UTC, timeout errorMessage ILIKE '%statement timeout%', route regex '^/practicas/[0-9a-fA-F-]{36}([/?]|$)'. Route split: 30 GET render/RSC-payload rows, 14 practica IDs; 4 GET render/RSC rows, 3 IDs; 5 POST/action RSC-payload rows, 3 IDs; 1 review-postcommit-side-effect-failed notification row, 1 ID. Of the 40, unique route IDs=20, unknown ID=0; actorUserId NULL=39, effectiveUserId NULL=40, detail.clientSession NULL=40. Do not infer distinct affected users from route IDs. Five-minute gap clusters (class-partitioned): render 8 clusters: 9/3 IDs (09-16 23:04:09.780684-23:04:59.827605Z), 3/2 (09-21 23:04:40.035885-23:05:01.926351Z), 1/1 (09-22 02:15:37.883853Z), 5/1 (09-22 13:23:09.673215-13:23:18.917939Z), 3/2 (09-23 20:30:22.133091-20:31:06.090106Z), 4/3 (09-27 20:14:12.430074-20:14:24.049164Z), 8/4 (09-27 20:33:31.897651-20:37:27.456709Z), 1/1 (09-28 21:31:07.767610Z); POST/action 2 clusters: 4/2 (09-18 01:14:53.847502-01:16:14.512972Z), 1/1 (09-25 10:35:21.623725Z). Notification-side-effect 1/1 (10-05 11:50:09.752971Z). Format rows/distinct practica IDs.\n\nEvent census SQL (path ID only in aggregate; no ID values selected):\nWITH e AS (SELECT "createdAt", route, category, action, "actorUserId", "effectiveUserId", detail, substring(route from '^/practicas/([0-9a-fA-F-]{36})') AS path_id, coalesce(detail->>'method','?') AS method, coalesce(detail->>'routeType','?') AS route_type, coalesce(detail->>'renderSource','?') AS render_source FROM public."appEvents" WHERE "createdAt">=timestamptz '2026-09-14 00:00:00+00' AND route ~ '^/practicas/[0-9a-fA-F-]{36}([/?]|$)' AND "errorMessage" ILIKE '%statement timeout%') SELECT category,action,method,route_type,render_source,count(*),count(DISTINCT path_id),count(*) FILTER (WHERE path_id IS NULL),count(*) FILTER (WHERE "actorUserId" IS NULL),count(*) FILTER (WHERE "effectiveUserId" IS NULL),count(*) FILTER (WHERE detail->>'clientSession' IS NULL),min("createdAt"),max("createdAt") FROM e GROUP BY 1,2,3,4,5 ORDER BY 1,2,3,4,5;\n\nCluster query used the same filtered CTE, classified notification when category='practica' AND action='review-postcommit-side-effect-failed', POST/action when method='POST' OR route_type='action', else render; then new cluster when lag(createdAt) per class exceeds interval '5 minutes', cumulative SUM(new_cluster), group by class+cluster for count, count(distinct path_id), min/max time. Results above.\n\nWorst-real-practica selection used active practicas and counts in practicaHistorialEntries, practicaReviews, practicaComentarios (LEFT JOIN each grouped by practicaId), ORDER BY combined count DESC, history DESC, reviews DESC, comments DESC, p.id LIMIT 1. Snapshot: 4,657 active; max history 57, max reviews 7, max comments 3, max combined 64, one row at combined max; selected worst row had 57 history + 7 reviews + 0 comments. No raw ID/name/PII retained.\n\nBundle probe attempted exactly: BEGIN READ ONLY; PREPARE detail_bundle_probe(uuid) AS SELECT * FROM public.get_practica_detail_bundle(); EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) EXECUTE detail_bundle_probe(<selected UUID>); ROLLBACK. Result: permission denied for function get_practica_detail_bundle under agent_db_mars_ca; no elevated/borrowed credential used. Thus no bundle plan or measured bundle latency.\n\nFirst-row probe: source-exact getPracticaDetail SQL from src/lib/practica.ts:763-805, prepared with the same selected UUID and EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON). Planning 110.398ms, execution 15.774ms; plan shared hits 758, execution shared hits 39, shared reads 0, one row. Not close to 10s in this warm single-session read; this is not a cold/concurrent production replay. The first-row plan is not evidence that the full route is safe or that the bundle caused timeouts.\n\nCross-reference: MARS-743 owns shared-stall investigation; MARS-769 includes bundle/history optimization (182a/b/c already applied). These results do not establish cause for the historical burst; app-side page still fans out detail + bundle + lookups/access/edit-lock queries. No DB changes.
• db-mars-ca note · 1w ago
  Correction and exact SQL addendum, same read-only measurement (the earlier note's \n sequences were literal separators, and its rendered bundle-call line omitted the prepared parameter). No raw IDs/PII below. 1) Exact route aggregate SQL executed: WITH e AS ( SELECT "createdAt", route, category, action, "actorUserId", "effectiveUserId", detail, substring(route from '^/practicas/([0-9a-fA-F-]{36})') AS path_id, coalesce(detail->>'method','?') AS method, coalesce(detail->>'routeType','?') AS route_type, coalesce(detail->>'renderSource','?') AS render_source FROM public."appEvents" WHERE "createdAt">=timestamptz '2026-09-14 00:00:00+00' AND route ~ '^/practicas/[0-9a-fA-F-]{36}([/?]|$)' AND "errorMessage" ILIKE '%statement timeout%' ) SELECT category,action,method,route_type,render_source,count(*), count(DISTINCT path_id),count(*) FILTER (WHERE path_id IS NULL), count(*) FILTER (WHERE "actorUserId" IS NULL), count(*) FILTER (WHERE "effectiveUserId" IS NULL), count(*) FILTER (WHERE detail->>'clientSession' IS NULL), min("createdAt"),max("createdAt") FROM e GROUP BY 1,2,3,4,5 ORDER BY 1,2,3,4,5; 2) Exact 5-minute cluster SQL logic: reuse that CTE e; derive event_class with category='practica' AND action='review-postcommit-side-effect-failed' => notification-side-effect; else method='POST' OR route_type='action' => post-action; else render. In the classified CTE calculate new_cluster=1 when lag(createdAt) partitioned by event_class ordered by createdAt is NULL or current-lag > interval '5 minutes', else 0. In clustered CTE compute sum(new_cluster) over (partition by event_class order by createdAt) as cluster_no. Final SELECT event_class,cluster_no,count(*),count(distinct path_id),min(createdAt),max(createdAt) GROUP BY event_class,cluster_no ORDER BY event_class,cluster_no. The exact executed SQL returned the 11 clusters enumerated in the prior note. 3) Exact workload-size SQL: WITH h AS (SELECT "practicaId",count(*) n FROM public."practicaHistorialEntries" GROUP BY 1), r AS (SELECT "practicaId",count(*) n FROM public."practicaReviews" GROUP BY 1), c AS (SELECT "practicaId",count(*) n FROM public."practicaComentarios" GROUP BY 1) SELECT p.id,coalesce(h.n,0) history_count,coalesce(r.n,0) review_count,coalesce(c.n,0) comment_count,coalesce(h.n,0)+coalesce(r.n,0)+coalesce(c.n,0) combined_count FROM public."practicas" p LEFT JOIN h ON h."practicaId"=p.id LEFT JOIN r ON r."practicaId"=p.id LEFT JOIN c ON c."practicaId"=p.id WHERE p."deletedAt" IS NULL ORDER BY combined_count DESC,history_count DESC,review_count DESC,comment_count DESC,p.id LIMIT 1; The client retained only counts; selected ID was not written to BWI. 4) Correct bundle probe statements: PREPARE detail_bundle_probe(uuid) AS SELECT * FROM public.get_practica_detail_bundle($1); then EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) EXECUTE detail_bundle_probe(:'candidate_id');. The server returned permission denied for function get_practica_detail_bundle during EXPLAIN; no plan was produced. candidate_id was a psql variable, not printed. The previous note's probe line missing ($1) was a transcription error; actual prepared statement included $1. 5) First-row query actually benchmarked is getPracticaDetail's SQL at src/lib/practica.ts:763-805, with its SELECT list and joins unchanged and WHERE vp."id"=$1, prepared as a uuid and EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) EXECUTE'd with that selected candidate. Measured plan: planning 110.398ms/758 shared hits, execution 15.774ms/39 shared hits/0 reads, one row. Warm single-session only.
• db-mars-ca note · 1w ago
  Exact SQL/results addendum; read-only own role agent_db_mars_ca. The earlier notes contain literal \n separators from transport; this block is newline-formatted for direct reuse. No identifiers or PII. Route census: WITH e AS ( SELECT "createdAt",route,category,action,"actorUserId","effectiveUserId",detail, substring(route from '^/practicas/([0-9a-fA-F-]{36})') AS path_id, coalesce(detail->>'method','?') AS method, coalesce(detail->>'routeType','?') AS route_type, coalesce(detail->>'renderSource','?') AS render_source FROM public."appEvents" WHERE "createdAt">=timestamptz '2026-09-14 00:00:00+00' AND route ~ '^/practicas/[0-9a-fA-F-]{36}([/?]|$)' AND "errorMessage" ILIKE '%statement timeout%' ) SELECT category,action,method,route_type,render_source,count(*), count(DISTINCT path_id),count(*) FILTER(WHERE path_id IS NULL), count(*) FILTER(WHERE "actorUserId" IS NULL), count(*) FILTER(WHERE "effectiveUserId" IS NULL), count(*) FILTER(WHERE detail->>'clientSession' IS NULL), min("createdAt"),max("createdAt") FROM e GROUP BY 1,2,3,4,5 ORDER BY 1,2,3,4,5; Cluster derivation over the same filtered CTE: event_class is notification-side-effect for category='practica' AND action='review-postcommit-side-effect-failed'; post-action for method='POST' OR route_type='action'; otherwise render. Mark a new cluster when lag(createdAt) within event_class ordered by createdAt is NULL or gap > interval '5 minutes'; cumulative SUM(new_cluster) over event_class gives cluster_no. Group by event_class,cluster_no and report count(*), count(DISTINCT path_id), min/max(createdAt). Results are in preceding note. Workload sizing (actual selected UUID captured only in psql variable, never displayed or recorded): WITH h AS (SELECT "practicaId",count(*) n FROM public."practicaHistorialEntries" GROUP BY 1), r AS (SELECT "practicaId",count(*) n FROM public."practicaReviews" GROUP BY 1), c AS (SELECT "practicaId",count(*) n FROM public."practicaComentarios" GROUP BY 1) SELECT p.id,coalesce(h.n,0) history_count,coalesce(r.n,0) review_count, coalesce(c.n,0) comment_count, coalesce(h.n,0)+coalesce(r.n,0)+coalesce(c.n,0) combined_count FROM public."practicas" p LEFT JOIN h ON h."practicaId"=p.id LEFT JOIN r ON r."practicaId"=p.id LEFT JOIN c ON c."practicaId"=p.id WHERE p."deletedAt" IS NULL ORDER BY combined_count DESC,history_count DESC,review_count DESC,comment_count DESC,p.id LIMIT 1; Bundle EXPLAIN statements actually issued: PREPARE detail_bundle_probe(uuid) AS SELECT * FROM public.get_practica_detail_bundle($1); EXPLAIN (ANALYZE,BUFFERS,FORMAT JSON) EXECUTE detail_bundle_probe(:'candidate_id'); The server denied execution: permission denied for function get_practica_detail_bundle. Therefore no bundle plan/timing exists. An earlier note accidentally omitted ($1) in its displayed SQL; prepared statement did include it. The first-row benchmark used the unchanged source SQL at src/lib/practica.ts:763-805 (all selected columns/joins from public."vPracticas" plus users/comisiones; WHERE vp."id"=$1), prepared as UUID and EXPLAIN (ANALYZE,BUFFERS,FORMAT JSON) EXECUTE'd using the psql candidate_id variable. Planning 110.398ms / 758 shared hits; execution 15.774ms / 39 shared hits / 0 reads; one row. Warm single-session sample, not cold or concurrency evidence.
• coder-mars-ca progress · 1w ago
  Temporal correlation (2026-10-06): MARS-769 migration 182a/b/c was applied by 2026-09-28 03:58Z; fresh-connection bundle samples then were 12-13ms (4/5), 46,913-row backfill diff 0. Of 34 historical detail GET-render timeout rows, the last and only one after that migration is 2026-09-28 21:31:07.767Z. It falls inside MARS-743's 21:30:40-21:31:15Z shared-latency burst: 13 DB cancels across 9 queryids; routine programa lookup 2.09-2.72s, appEvents INSERT 2.74-9s, vUsers lookup 2.1-3.3s. MARS-743 also records one get_practica_detail_bundle cancel in that burst. This is correlation, not proof of which awaited statement failed for the render. No isolated post-rewrite detail-render timeout is currently evidenced. The 2026-10-05 detail-route row is a review notification side effect, not a GET render. DB seat's source-exact first-row vPracticas EXPLAIN was 110.4ms planning/15.8ms execution on a warm single session; bundle EXPLAIN was correctly attempted with $1 but denied EXECUTE for agent_db_mars_ca, so no current worst-practica full-route/bundle benchmark exists. Do not call the 40 historical rows 40 current bundle failures or ship a speculative query rewrite. Route-specific root cause remains unproven; MARS-743 owns shared-stall attribution and MARS-769 owns bundle cost.
• coder-mars-ca completed · 1w ago
  Duplicate of MARS-743 per pmmaster 2026-10-06. Full route census, cluster split, post-182c timeline, warm worst-practica first-row measurement, and bundle EXPLAIN permission gap copied to MARS-743; no independent current detail-route defect established and no code change made. MARS-743 remains p1 owner for shared-stall attribution.